New test infrastructure for producing verbose logs in failing tests.

chrome/test/base/log_file_reader_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/log_file_reader_win.h"
+
+#include "base/debug/trace_event_win.h"
+#include "base/file_path.h"
+#include "base/lazy_instance.h"
+#include "base/logging_win.h"
+#include "base/synchronization/lock.h"
+#include "base/win/event_trace_consumer.h"
+#include "chrome/test/base/mof_data_parser_win.h"
+
+namespace logging_win {
+
+namespace {
+
+// TODO(grt) This reverses a mapping produced by base/logging_win.cc's
+// LogEventProvider::LogMessage.  LogEventProvider should expose a way to map an
+// event level back to a log severity.
+logging::LogSeverity EventLevelToSeverity(uint8 level) {
+  switch (level) {
+  case TRACE_LEVEL_NONE:
+    NOTREACHED();
+    return logging::LOG_ERROR;
+  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;
+  }
+}
+
+// TODO(grt) This reverses a mapping produced by base/debug/trace_event_win.cc's
+// TraceEventETWProvider::TraceEvent.  TraceEventETWProvider should expose a way
+// to map an event type back to a trace type.
+char EventTypeToTraceType(uint8 event_type) {
+  switch (event_type) {
+    case base::debug::kTraceEventTypeBegin:
+      return TRACE_EVENT_PHASE_BEGIN;
+      break;
+    case base::debug::kTraceEventTypeEnd:
+      return TRACE_EVENT_PHASE_END;
+      break;
+    case base::debug::kTraceEventTypeInstant:
+      return TRACE_EVENT_PHASE_INSTANT;
+      break;
+    default:
+      NOTREACHED();
+      return '\0';
+      break;
+  }
+}
+
+class LogFileReader {
+ public:
+  explicit LogFileReader(LogFileDelegate* delegate);
+  ~LogFileReader();
+
+  static void ReadFile(const FilePath& log_file, LogFileDelegate* delegate);
+
+ 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> > {
+   public:
+    TraceConsumer() { }
+    static void ProcessEvent(EVENT_TRACE* event) { (*ProcessEventFn)(event); }
+   private:
+    DISALLOW_COPY_AND_ASSIGN(TraceConsumer);
+  };
+
+  // Delegates to DispatchEvent() of the current LogDumper instance.
+  static void ProcessEvent(EVENT_TRACE* event);
+
+  // Handlers for the supported event types.
+  bool OnLogMessageEvent(const EVENT_TRACE* event);
+  bool OnLogMessageFullEvent(const EVENT_TRACE* event);
+  bool OnTraceEvent(const EVENT_TRACE* event);
+  bool OnFileHeader(const EVENT_TRACE* event);
+
+  // Parses an event and passes it along to the delegate for processing.
+  void DispatchEvent(const EVENT_TRACE* event);
+
+  // Reads the file using a trace consumer.  |ProcessEvent| will be invoked for
+  // each event in the file.
+  void Read(const FilePath& log_file);
+
+  // Protects use of the class; only one instance may be live at a time.
+  static base::LazyInstance<base::Lock>::Leaky reader_lock_;
+
+  // The currently living instance.
+  static LogFileReader* instance_;
+
+  // The delegate to be notified of events.
+  LogFileDelegate* delegate_;
+};
+
+// static
+base::LazyInstance<base::Lock>::Leaky LogFileReader::reader_lock_ =
+    LAZY_INSTANCE_INITIALIZER;
+
+// static
+LogFileReader* LogFileReader::instance_ = NULL;
+
+LogFileReader::LogFileReader(LogFileDelegate* delegate)
+    : delegate_(delegate) {
+  DCHECK(instance_ == NULL);
+  DCHECK(delegate != NULL);
+  instance_ = this;
+}
+
+LogFileReader::~LogFileReader() {
+  DCHECK_EQ(instance_, this);
+  instance_ = NULL;
+}
+
+// static
+void LogFileReader::ProcessEvent(EVENT_TRACE* event) {
+  if (instance_ != NULL)
+    instance_->DispatchEvent(event);
+}
+
+bool LogFileReader::OnLogMessageEvent(const EVENT_TRACE* event) {
+  base::StringPiece message;
+  MofDataParser parser(event);
+  if (parser.ReadString(&message) && parser.empty()) {
+    delegate_->OnLogMessage(event,
+                            EventLevelToSeverity(event->Header.Class.Level),
+                            message);
+    return true;
+  }
+  return false;
+}
+
+bool LogFileReader::OnLogMessageFullEvent(const EVENT_TRACE* event) {
+  DWORD stack_depth = 0;
+  const intptr_t* backtrace = NULL;
+  int line = 0;
+  base::StringPiece file;
+  base::StringPiece message;
+  MofDataParser parser(event);
+
+  if (parser.ReadDWORD(&stack_depth) &&

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

Presumably this maps to some writing code somewhere else. Can you add a
reference?

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

Done.

+      parser.ReadPointerArray(stack_depth, &backtrace) &&
+      parser.ReadInt(&line) &&
+      parser.ReadString(&file) &&
+      parser.ReadString(&message) &&
+      parser.empty()) {
+    delegate_->OnLogMessageFull(event,
+        EventLevelToSeverity(event->Header.Class.Level), stack_depth, backtrace,
+        line, file, message);
+    return true;
+  }
+  return false;
+}
+
+bool LogFileReader::OnTraceEvent(const EVENT_TRACE* event) {
+  MofDataParser parser(event);
+  base::StringPiece name;
+  intptr_t id = 0;
+  base::StringPiece extra;
+  DWORD stack_depth = 0;
+  const intptr_t* backtrace = NULL;
+
+  if (parser.ReadString(&name) &&

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

Ditto.

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

Done.

+      parser.ReadPointer(&id) &&
+      parser.ReadString(&extra) &&
+      (parser.empty() ||
+       parser.ReadDWORD(&stack_depth) &&
+       parser.ReadPointerArray(stack_depth, &backtrace) &&
+       parser.empty())) {
+    delegate_->OnTraceEvent(event, name,
+        EventTypeToTraceType(event->Header.Class.Type), id, extra, stack_depth,
+        backtrace);
+    return true;
+  }
+  return false;
+}
+
+bool LogFileReader::OnFileHeader(const EVENT_TRACE* event) {
+  MofDataParser parser(event);
+  const TRACE_LOGFILE_HEADER* header = NULL;
+
+  if (parser.ReadStructure(&header)) {
+    delegate_->OnFileHeader(event, header);
+    return true;
+  }
+  return false;
+}
+
+void LogFileReader::DispatchEvent(const EVENT_TRACE* event) {
+  bool parsed = true;
+
+  if (IsEqualGUID(event->Header.Guid, logging::kLogEventId)) {
+    if (event->Header.Class.Type == logging::LOG_MESSAGE)
+      parsed = OnLogMessageEvent(event);
+    else if (event->Header.Class.Type == logging::LOG_MESSAGE_FULL)
+      parsed = OnLogMessageFullEvent(event);
+  } else if (IsEqualGUID(event->Header.Guid, base::debug::kTraceEventClass32)) {
+    parsed = OnTraceEvent(event);
+  } else if (IsEqualGUID(event->Header.Guid, EventTraceGuid)) {
+    parsed = OnFileHeader(event);
+  } else {
+    DCHECK(parsed);
+    delegate_->OnUnknownEvent(event);
+  }
+  if (!parsed)
+    delegate_->OnUnparsableEvent(event);
+}
+
+void LogFileReader::Read(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();
+  }
+}
+
+// static
+void LogFileReader::ReadFile(const FilePath& log_file,
+                             LogFileDelegate* delegate) {
+  base::AutoLock lock(reader_lock_.Get());
+
+  LogFileReader(delegate).Read(log_file);
+}
+
+}  // namespace
+
+LogFileDelegate::LogFileDelegate() {
+}
+
+LogFileDelegate::~LogFileDelegate() {
+}
+
+void ReadLogFile(const FilePath& log_file, LogFileDelegate* delegate) {
+  DCHECK(delegate);
+  LogFileReader::ReadFile(log_file, delegate);
+}
+
+}  // logging_win