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..fc5e2a1f8c3fecb3792ac9603d5658b64b4f36f6
--- /dev/null
+++ b/chrome/test/base/file_logger_win.cc
@@ -0,0 +1,805 @@
+// 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 <evntrace.h>
+#include <guiddef.h>
+#include <objbase.h>  // for StringFromGUID2

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

any reason for the comment?

[grt (UTC plus 2), 2012/03/06 03:24:57]

Not really.  Removed.

+
+#include <iomanip>
+#include <ios>  // For std::hex
+
+#include "base/debug/trace_event_win.h"
+#include "base/logging.h"
+#include "base/file_path.h"
+#include "base/logging_win.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/string_piece.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 }
+};

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

COMPILE_ASSERT on the arraysize vs the enum in the header.

[grt (UTC plus 2), 2012/03/06 03:24:57]

Kinda done.  I checked it against the bitfield of all providers.

+
+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;
+
+
+// Writes a timestamp.
+void WriteTimeStamp(LARGE_INTEGER time_stamp, std::ostream& out) {

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

don't use non-const references

[grt (UTC plus 2), 2012/03/06 03:24:57]

In the case of streams, I think it makes more sense to use a non-const ref than
a pointer.  Although there are some hits for the latter in the codebase, the
former seems much more prevalent.

+  // Get a nice SYSTEMTIME from the time_stamp.
+  FILETIME event_time = {};
+  event_time.dwLowDateTime = time_stamp.LowPart;
+  event_time.dwHighDateTime = time_stamp.HighPart;
+  SYSTEMTIME system_time = {};
+  FileTimeToSystemTime(&event_time, &system_time);
+
+  // SYSTEMTIME only has millisecond accuracy.  Do some conversions and math to
+  // get the sub-second time (number of 100ns ticks).
+  system_time.wMilliseconds = 0;
+  FILETIME coarse_event_time = {};
+  SystemTimeToFileTime(&system_time, &coarse_event_time);
+  ULARGE_INTEGER coarse_value;
+  coarse_value.HighPart = coarse_event_time.dwHighDateTime;
+  coarse_value.LowPart = coarse_event_time.dwLowDateTime;
+  coarse_value.QuadPart = time_stamp.QuadPart - coarse_value.QuadPart;

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

consider mentioning that ULARGE_INTEGER is a union and that doing this again
sets the LowPart. This might not be obvious given the way coarse_value is reused
here.

[grt (UTC plus 2), 2012/03/06 03:24:57]

Switched to using base/time.h's facilities, giving up on the idea of sub-ms
precision.

+  DCHECK_EQ(coarse_value.HighPart, static_cast<DWORD>(0));
+  DCHECK_LT(coarse_value.LowPart, static_cast<DWORD>(10000000));
+
+  out << std::setfill('0')
+      << std::setw(2) << system_time.wMonth
+      << std::setw(2) << system_time.wDay
+      << '/'
+      << std::setw(2) << system_time.wHour
+      << std::setw(2) << system_time.wMinute
+      << std::setw(2) << system_time.wSecond
+      << '.'
+      << std::setw(7) << coarse_value.LowPart;
+}
+
+// Converts an ETW level created by logging::LogEventProvider back to its
+// corresponding severity.

[erikwright (departed), 2012/03/05 19:55:30]

I suspect this corresponds to an inverse switch statement somewhere. If so, can
you provide a reference?

Would it be appropriate to expose two-way conversion functions at that point?

+logging::LogSeverity EventLevelToSeverity(uint8 level) {
+  switch (level) {
+    case TRACE_LEVEL_NONE:
+      NOTREACHED();
+    case TRACE_LEVEL_FATAL:
+      return logging::LOG_FATAL;
+    case TRACE_LEVEL_ERROR:
+      return logging::LOG_ERROR;
+    case TRACE_LEVEL_WARNING:
+      return logging::LOG_WARNING;
+    case TRACE_LEVEL_INFORMATION:
+      return logging::LOG_INFO;
+    default:
+      // Trace levels above information correspond to negative severity levels,
+      // which are used for VLOG verbosity levels.
+      return TRACE_LEVEL_INFORMATION - level;
+  }
+}
+
+// Writes a severity level to the stream a la LogMessage::Init.
+void WriteSeverity(logging::LogSeverity severity, std::ostream& out) {

[erikwright (departed), 2012/03/05 19:55:30]

This is how base/logging.h does it:

http://code.google.com/codesearch#OAMlx_jo-ck/src/base/logging.cc&l=74

Might be a nice TODO to expose & reuse that functionality for severity >= 0?

+  switch (severity) {
+    case logging::LOG_INFO:
+      out << "INFO";
+      break;
+    case logging::LOG_WARNING:
+      out << "WARNING";
+      break;
+    case logging::LOG_ERROR:
+      out << "ERROR";
+      break;
+    case logging::LOG_ERROR_REPORT:
+      out << "ERROR_REPORT";
+      break;
+    case logging::LOG_FATAL:
+      out << "FATAL";
+      break;
+    default:
+      if (severity < 0)
+        out << "VERBOSE" << -severity;
+      else
+        NOTREACHED();
+      break;
+  }
+}
+
+// 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 delegates to a given (at
+  // compile-time) event processing function.
+  template<void (*ProcessEventFn)(EVENT_TRACE*)>
+  class TraceConsumer
+      : public base::win::EtwTraceConsumerBase<TraceConsumer<ProcessEventFn> > {

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

template abuse alert.. template abuse alert.. 

It looks like this is only used in one place? If so, this is overly complicated.

[robertshield, 2012/03/05 19:57:07]

Taking a look at the implementation of EtwTraceConsumerBase, I see why you did
this, and it's actually quite neat. I retract my previous mutterings.

[grt (UTC plus 2), 2012/03/06 03:24:57]

Thanks.  I didn't like the other obvious options (having LogDumper derive from
EtwTraceConsumerBase, using "friend" so this could delegate to the active
LogDumper instance, or passing a function pointer at runtime).  I kinda like
this since the compiler can, in theory, peel away a level of indirection at
compile-time.

+   public:
+    TraceConsumer() { }
+    static void ProcessEvent(EVENT_TRACE* event) { (*ProcessEventFn)(event); }
+   private:
+    DISALLOW_COPY_AND_ASSIGN(TraceConsumer);
+  };
+
+  // A parser for Mof data found in an EVENT_TRACE object as formatted by

[erikwright (departed), 2012/03/05 19:55:30]

I find it shocking that this needs to be written but I couldn't find an existing
implementation. It does seem like it might be similar or a replacement of this
code in Syzygy:

http://code.google.com/p/sawbuck/source/search?q=MOF+file%3A%5C.cc&origq=MOF+...

Perhaps if one or the other got pushed down to base/ at some point they could
share code.

In any case, this code is complicated enough that I think it should live in a
separate file.

+  // Chromium-related classes.
+  class MofDataParser {
+   public:
+    explicit MofDataParser(EVENT_TRACE* event);
+    bool ReadDWORD(DWORD* value) {
+      return ReadPrimitive(value);
+    }
+    bool ReadInt(int* value) {
+      return ReadPrimitive(value);
+    }
+    bool ReadVoidPointer(void** value) {
+      return ReadPrimitive(value);
+    }
+    bool ReadVoidPointerArray(DWORD size, void* const** values) {
+      return ReadPointerArray(size, values);
+    }
+    // Reads an arbitrary data structure within the data.
+    template<typename T> bool ReadStructure(const T** value) {
+      if (length_ < sizeof(**value))
+        return false;
+      *value = reinterpret_cast<const T*>(scan_);
+      Advance(sizeof(**value));
+      return true;
+    }
+    // Reads a null-terminated string from the data.  A trailing newline, if
+    // present, is stripped.
+    bool ReadString(base::StringPiece* value);
+    bool empty() { return length_ == 0; }
+
+   private:
+    void Advance(size_t num_bytes) {
+      scan_ += num_bytes;
+      length_ -= num_bytes;
+    }
+    template<typename T> bool ReadPrimitive(T* value) {
+      if (length_ < sizeof(*value))
+        return false;
+      *value = *reinterpret_cast<const T*>(scan_);
+      Advance(sizeof(*value));
+      return true;
+    }
+    template<typename T> bool ReadPointerArray(DWORD size, T* const** values) {
+      if (length_ < sizeof(*values) * size)
+        return false;
+      *values = reinterpret_cast<T* const*>(scan_);
+      Advance(sizeof(*values) * size);
+      return true;
+    }
+
+    const uint8* scan_;
+    uint32 length_;
+  };
+
+  // An interface for handling Mof data.
+  class MofData {
+   public:
+    virtual ~MofData();
+
+    // Parses the data in |event|, returning true on success; false otherwise.
+    virtual bool Initialize(EVENT_TRACE* event) = 0;
+
+    // Writes the event level.
+    virtual bool WriteLevel(uint8 level, std::ostream& out) = 0;
+
+    // Writes context information.
+    virtual void WriteContext(std::ostream& out) = 0;
+
+    // Writes the meat of the data.
+    virtual void WriteData(std::ostream& out) = 0;
+
+   protected:
+    MofData();
+  };
+
+  // A MofData implementation for events created by Chromium's LogEventProvider
+  // when the ENABLE_LOG_MESSAGE_ONLY flag is set.
+  class LogMessageData : public MofData {
+   public:
+    LogMessageData();
+    virtual ~LogMessageData();
+    virtual bool Initialize(EVENT_TRACE* event) OVERRIDE;
+    virtual bool WriteLevel(uint8 level, std::ostream& out) OVERRIDE;
+    virtual void WriteContext(std::ostream& out) OVERRIDE;
+    virtual void WriteData(std::ostream& out) OVERRIDE;
+
+   private:
+    base::StringPiece message_;
+    DISALLOW_COPY_AND_ASSIGN(LogMessageData);
+  };
+
+  // A MofData implementation for events created by Chromium's LogEventProvider
+  // when the ENABLE_LOG_MESSAGE_ONLY flag is not set.
+  class LogMessageFullData : public MofData {
+   public:
+    LogMessageFullData();
+    virtual ~LogMessageFullData();
+    virtual bool Initialize(EVENT_TRACE* event) OVERRIDE;
+    virtual bool WriteLevel(uint8 level, std::ostream& out) OVERRIDE;
+    virtual void WriteContext(std::ostream& out) OVERRIDE;
+    virtual void WriteData(std::ostream& out) OVERRIDE;
+
+   private:
+    DWORD stack_depth_;
+    void *const * backtrace_;
+    int line_;
+    base::StringPiece file_;
+    base::StringPiece message_;
+    DISALLOW_COPY_AND_ASSIGN(LogMessageFullData);
+  };
+
+  // A MofData implementation for events created by Chromium's
+  // TraceEventETWProvider.
+  class TraceEventData : public MofData {
+   public:
+    TraceEventData();
+    virtual ~TraceEventData();
+    virtual bool Initialize(EVENT_TRACE* event) OVERRIDE;
+    virtual bool WriteLevel(uint8 level, std::ostream& out) OVERRIDE;
+    virtual void WriteContext(std::ostream& out) OVERRIDE;
+    virtual void WriteData(std::ostream& out) OVERRIDE;
+
+   private:
+    const char* type_;
+    base::StringPiece name_;
+    void* id_;
+    base::StringPiece extra_;
+    DWORD stack_depth_;
+    void *const * backtrace_;
+    DISALLOW_COPY_AND_ASSIGN(TraceEventData);
+  };
+
+  // A MofData implementation for the TRACE_LOGFILE_HEADER event at the start of
+  // log files.
+  class LogfileHeaderData : public MofData {
+   public:
+    LogfileHeaderData();
+    virtual ~LogfileHeaderData();
+    virtual bool Initialize(EVENT_TRACE* event) OVERRIDE;
+    virtual bool WriteLevel(uint8 level, std::ostream& out) OVERRIDE;
+    virtual void WriteContext(std::ostream& out) OVERRIDE;
+    virtual void WriteData(std::ostream& out) OVERRIDE;
+
+   private:
+    const TRACE_LOGFILE_HEADER* header_;
+    DISALLOW_COPY_AND_ASSIGN(LogfileHeaderData);
+  };
+
+  // A pointer to a function that creates a new instance of some MofData
+  // implementation.
+  typedef MofData* (*MofDataFactoryFn)();
+
+  // Returns a new instance of a MofData implementation.
+  template<class MofDataType> static MofData* CreateMofData() {
+    return new MofDataType();
+  }
+
+  explicit LogDumper(std::ostream& out);
+  ~LogDumper();
+
+  // Returns a factory function to create the MofData implementation
+  // corresponding to an EVENT_TRACE instance of the given event class and type.
+  static MofDataFactoryFn GetMofDataFactory(const GUID& event_class,
+                                            uint8 type);
+
+  // Delegates to DumpEvent() of the current LogDumper instance.
+  static void ProcessEvent(EVENT_TRACE* event);
+
+  // Dumps the event.
+  void DumpEvent(EVENT_TRACE* event);
+
+  // Consumes all events in |log_file|, dumping them to the output stream.
+  void Consume(const FilePath& log_file);
+
+  // The current instance.
+  static LogDumper* instance_;
+  std::ostream* out_;
+
+  DISALLOW_COPY_AND_ASSIGN(LogDumper);
+};
+
+// LogDumper::MofDataParser implementation
+
+LogDumper::MofDataParser::MofDataParser(EVENT_TRACE* event)
+    : scan_(reinterpret_cast<CONST uint8*>(event->MofData)),
+      length_(event->MofLength) {
+}
+
+bool LogDumper::MofDataParser::ReadString(base::StringPiece* value) {
+  const uint8* str_scan = scan_;
+  const uint8* const str_end = str_scan + length_;
+  while (str_scan < str_end && *str_scan != 0)
+    ++str_scan;
+  if (str_scan == str_end)
+    return false;
+  size_t string_length = str_scan - scan_;
+  bool has_trailing_newline = (string_length > 0 && str_scan[-1] == '\n');
+  value->set(reinterpret_cast<const char*>(scan_),
+             has_trailing_newline ? string_length - 1 : string_length);
+  Advance(string_length + 1);
+  return true;
+}
+
+// LogDumper::MofData implementation
+
+LogDumper::MofData::MofData() {
+}
+
+LogDumper::MofData::~MofData() {
+}
+
+// LogDumper::LogMessageData implementation
+
+LogDumper::LogMessageData::LogMessageData() {
+}
+
+LogDumper::LogMessageData::~LogMessageData() {
+}
+
+bool LogDumper::LogMessageData::Initialize(EVENT_TRACE* event) {
+  MofDataParser parser(event);
+  return (parser.ReadString(&message_) &&
+          parser.empty());
+}
+
+bool LogDumper::LogMessageData::WriteLevel(uint8 level, std::ostream& out) {
+  WriteSeverity(EventLevelToSeverity(level), out);
+  return true;
+}
+
+void LogDumper::LogMessageData::WriteContext(std::ostream& out) {
+}
+
+void LogDumper::LogMessageData::WriteData(std::ostream& out) {
+  out << message_;
+}
+
+// LogDumper::LogMessageFullData implementation
+
+LogDumper::LogMessageFullData::LogMessageFullData()
+    : stack_depth_(),
+      backtrace_(),
+      line_() {
+}
+
+LogDumper::LogMessageFullData::~LogMessageFullData() {
+}
+
+bool LogDumper::LogMessageFullData::Initialize(EVENT_TRACE* event) {
+  MofDataParser parser(event);
+  return (parser.ReadDWORD(&stack_depth_) &&
+          parser.ReadVoidPointerArray(stack_depth_, &backtrace_) &&
+          parser.ReadInt(&line_) &&
+          parser.ReadString(&file_) &&
+          parser.ReadString(&message_) &&
+          parser.empty());
+}
+
+bool LogDumper::LogMessageFullData::WriteLevel(uint8 level, std::ostream& out) {
+  WriteSeverity(EventLevelToSeverity(level), out);
+  return true;
+}
+
+void LogDumper::LogMessageFullData::WriteContext(std::ostream& out) {
+  // Shamelessly borrowed from base/logging.cc LogMessage::Init()
+  base::StringPiece filename(file_);
+  size_t last_slash_pos = filename.find_last_of("\\/");
+  if (last_slash_pos != base::StringPiece::npos)
+    filename.remove_prefix(last_slash_pos + 1);
+
+  out << filename << '(' << line_ << ')';
+}
+
+void LogDumper::LogMessageFullData::WriteData(std::ostream& out) {
+  out << message_;
+}
+
+// LogDumper::TraceEventData implementation
+
+LogDumper::TraceEventData::TraceEventData()
+    : type_(),
+      id_(),
+      stack_depth_(),
+      backtrace_() {
+}
+
+LogDumper::TraceEventData::~TraceEventData() {
+}
+
+bool LogDumper::TraceEventData::Initialize(EVENT_TRACE* event) {
+  switch (event->Header.Class.Type) {
+    case base::debug::kTraceEventTypeBegin:
+      type_ = "BEGIN";
+      break;
+    case base::debug::kTraceEventTypeEnd:
+      type_ = "END";
+      break;
+    case base::debug::kTraceEventTypeInstant:
+      type_ = "INSTANT";
+      break;
+    default:
+      NOTREACHED();
+      type_ = "";
+      break;
+  }
+  MofDataParser parser(event);
+  return (parser.ReadString(&name_) &&
+          parser.ReadVoidPointer(&id_) &&
+          parser.ReadString(&extra_) &&
+          (parser.empty() ||
+           parser.ReadDWORD(&stack_depth_) &&
+           parser.ReadVoidPointerArray(stack_depth_, &backtrace_) &&
+           parser.empty()));
+}
+
+void LogDumper::TraceEventData::WriteContext(std::ostream& out) {
+}
+
+bool LogDumper::TraceEventData::WriteLevel(uint8 level, std::ostream& out) {
+  out << type_;
+  return true;
+}
+
+void LogDumper::TraceEventData::WriteData(std::ostream& out) {
+  out << name_ << " " << extra_;
+}
+
+// LogDumper::LogfileHeaderData implementation
+
+LogDumper::LogfileHeaderData::LogfileHeaderData()
+    : header_() {
+}
+
+LogDumper::LogfileHeaderData::~LogfileHeaderData() {
+}
+
+bool LogDumper::LogfileHeaderData::Initialize(EVENT_TRACE* event) {
+  MofDataParser parser(event);
+  return parser.ReadStructure(&header_);
+}
+
+void LogDumper::LogfileHeaderData::WriteContext(std::ostream& out) {
+}
+
+bool LogDumper::LogfileHeaderData::WriteLevel(uint8 level, std::ostream& out) {
+  return false;
+}
+
+void LogDumper::LogfileHeaderData::WriteData(std::ostream& out) {
+  out << "Log captured from Windows "
+      << static_cast<int>(header_->VersionDetail.MajorVersion) << '.'
+      << static_cast<int>(header_->VersionDetail.MinorVersion) << '.'
+      << static_cast<int>(header_->VersionDetail.SubVersion) << '.'
+      << static_cast<int>(header_->VersionDetail.SubMinorVersion)
+      << ".  " << header_->EventsLost << " events lost, "
+      << header_->BuffersLost << " buffers lost.";
+}
+
+// LogDumper implementation
+
+// static
+LogDumper* LogDumper::instance_ = NULL;
+
+LogDumper::LogDumper(std::ostream& out) : out_(&out) {
+  CHECK(instance_ == NULL);
+  instance_ = this;
+}
+
+LogDumper::~LogDumper() {
+  CHECK_EQ(instance_, this);
+  instance_ = NULL;
+}
+
+// static
+LogDumper::MofDataFactoryFn LogDumper::GetMofDataFactory(
+    const GUID& event_class,
+    uint8 type) {

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

IMO this is needlessly complicated. Returning a factory here doesn't provide a
significant benefit to just new'ing up the right type of MofData and returning
it when I look at how this actually gets used.

You'll probably have cause to disagree with me though :-)

[grt (UTC plus 2), 2012/03/06 03:24:57]

No, I agree wholeheartedly.  This was left behind after other simplifications. 
Thanks for pointing it out.  I've removed the contagion.

+  if (IsEqualGUID(event_class, logging::kLogEventId)) {
+    if (type == logging::LOG_MESSAGE)
+      return &CreateMofData<LogMessageData>;
+    else if (type == logging::LOG_MESSAGE_FULL)
+      return &CreateMofData<LogMessageFullData>;
+  } else if (IsEqualGUID(event_class, base::debug::kTraceEventClass32)) {
+    return &CreateMofData<TraceEventData>;
+  } else if (IsEqualGUID(event_class, EventTraceGuid)) {
+    return &CreateMofData<LogfileHeaderData>;
+  }
+  return NULL;
+}
+
+// static
+void LogDumper::ProcessEvent(EVENT_TRACE* event) {
+  if (instance_ != NULL)
+    instance_->DumpEvent(event);
+}
+
+void LogDumper::DumpEvent(EVENT_TRACE* event) {
+  scoped_ptr<MofData> payload;
+  MofDataFactoryFn factory_fn = GetMofDataFactory(event->Header.Guid,
+                                                  event->Header.Class.Type);
+
+  if (factory_fn) {
+    payload.reset((*factory_fn)());
+    if (!payload->Initialize(event))
+      payload.reset();
+  }
+
+  *out_ << '[' << event->Header.ProcessId << ':'
+        << event->Header.ThreadId << ':';
+  WriteTimeStamp(event->Header.TimeStamp, *out_);
+  *out_ << ':';
+  if (!payload.get() || !payload->WriteLevel(event->Header.Class.Level, *out_))
+    *out_ << "level" << static_cast<int>(event->Header.Class.Level);
+  if (payload.get()) {
+    *out_ << ':';
+    payload->WriteContext(*out_);
+  }
+  *out_ << "] ";
+  if (payload.get()) {
+    payload->WriteData(*out_);
+  } else {
+    wchar_t guid[64];
+    StringFromGUID2(event->Header.Guid, &guid[0], arraysize(guid));
+    if (factory_fn)
+      *out_ << "parse error";
+    else
+      *out_ << "unsupported event";
+    *out_ << " (class=" << guid << ", type="
+          << static_cast<int>(event->Header.Class.Type) << ")";
+  }
+
+  *out_ << std::endl;
+}
+
+void LogDumper::Consume(const FilePath& log_file) {
+  TraceConsumer<&ProcessEvent> consumer;
+  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();
+  }
+}
+
+// static
+void LogDumper::DumpLog(const FilePath& log_file, std::ostream& out) {
+  LogDumper(out).Consume(log_file);
+}
+
+}  // 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.
+  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 {
+    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);
+}