chrome/test/logging/win/log_file_printer.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/logging/win/log_file_printer.h"

#include <windows.h>
#include <objbase.h>

#include <ios>
#include <iomanip>
#include <ostream>
#include <sstream>

#include "base/basictypes.h"
#include "base/compiler_specific.h"
#include "base/debug/trace_event.h"
#include "base/logging.h"
#include "base/string_number_conversions.h"
#include "base/string_piece.h"
#include "base/time.h"
#include "chrome/test/logging/win/log_file_reader.h"

namespace {

// TODO(grt) This duplicates private behavior in base/logging.cc's
// LogMessage::Init.  That behavior should be exposed and used here (possibly
// by moving this function to logging.cc, making it use log_severity_names, and
// publishing it in logging.h with BASE_EXPORT).
void WriteSeverityToStream(logging::LogSeverity severity, std::ostream* out) {
  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;
  }
}

// TODO(grt) This duplicates private behavior in base/logging.cc's
// LogMessage::Init.  That behavior should be exposed and used here (possibly
// by moving this function to logging.cc and publishing it in logging.h with
// BASE_EXPORT).
void WriteLocationToStream(const base::StringPiece& file,
                           int line,
                           std::ostream* out) {
  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 << ')';
}

// Returns a pretty string for the trace event types that appear in ETW logs.
const char* GetTraceTypeString(char event_type) {
  switch (event_type) {
    case TRACE_EVENT_PHASE_BEGIN:
      return "BEGIN";
      break;
    case TRACE_EVENT_PHASE_END:
      return "END";
      break;
    case TRACE_EVENT_PHASE_INSTANT:
      return "INSTANT";
      break;
    default:
      NOTREACHED();
      return "";
      break;
  }
}

class EventPrinter : public logging_win::LogFileDelegate {
 public:
  explicit EventPrinter(std::ostream* out);
  virtual ~EventPrinter();

  virtual void OnUnknownEvent(const EVENT_TRACE* event) OVERRIDE;

  virtual void OnUnparsableEvent(const EVENT_TRACE* event) OVERRIDE;

  virtual void OnFileHeader(const EVENT_TRACE* event,
                            const TRACE_LOGFILE_HEADER* header) OVERRIDE;

  virtual void OnLogMessage(const EVENT_TRACE* event,
                            logging::LogSeverity severity,
                            const base::StringPiece& message) OVERRIDE;

  virtual void OnLogMessageFull(const EVENT_TRACE* event,
                                logging::LogSeverity severity,
                                DWORD stack_depth,
                                const intptr_t* backtrace,
                                int line,
                                const base::StringPiece& file,
                                const base::StringPiece& message) OVERRIDE;

  virtual void OnTraceEvent(const EVENT_TRACE* event,
                            const base::StringPiece& name,
                            char type,
                            intptr_t id,
                            const base::StringPiece& extra,
                            DWORD stack_depth,
                            const intptr_t* backtrace) OVERRIDE;

 private:
  void PrintTimeStamp(LARGE_INTEGER time_stamp);
  void PrintEventContext(const EVENT_TRACE* event,
                         const base::StringPiece& level,
                         const base::StringPiece& context);
  void PrintBadEvent(const EVENT_TRACE* event, const base::StringPiece& error);

  std::ostream* out_;
  DISALLOW_COPY_AND_ASSIGN(EventPrinter);
};

EventPrinter::EventPrinter(std::ostream* out)
    : out_(out) {
}

EventPrinter::~EventPrinter() {
}

void EventPrinter::PrintTimeStamp(LARGE_INTEGER time_stamp) {
  FILETIME event_time = {};
  base::Time::Exploded time_exploded = {};
  event_time.dwLowDateTime = time_stamp.LowPart;
  event_time.dwHighDateTime = time_stamp.HighPart;
  base::Time::FromFileTime(event_time).LocalExplode(&time_exploded);

  *out_ << std::setfill('0')
        << std::setw(2) << time_exploded.month
        << std::setw(2) << time_exploded.day_of_month
        << '/'
        << std::setw(2) << time_exploded.hour
        << std::setw(2) << time_exploded.minute
        << std::setw(2) << time_exploded.second
        << '.'
        << std::setw(3) << time_exploded.millisecond;
}

// Prints the context info at the start of each line: pid, tid, time, etc.
void EventPrinter::PrintEventContext(const EVENT_TRACE* event,
                                     const base::StringPiece& level,
                                     const base::StringPiece& context) {
  *out_ << '[' << event->Header.ProcessId << ':'
        << event->Header.ThreadId << ':';
  PrintTimeStamp(event->Header.TimeStamp);
  if (!level.empty())
    *out_ << ':' << level;
  if (!context.empty())
    *out_ << ':' << context;
  *out_ << "] ";
}

// Prints a useful message for events that can't be otherwise printed.
void EventPrinter::PrintBadEvent(const EVENT_TRACE* event,
                                 const base::StringPiece& error) {
  wchar_t guid[64];
  StringFromGUID2(event->Header.Guid, &guid[0], arraysize(guid));
  *out_ << error << " (class=" << guid << ", type="
       << static_cast<int>(event->Header.Class.Type) << ")";
}

void EventPrinter::OnUnknownEvent(const EVENT_TRACE* event) {
  base::StringPiece empty;
  PrintEventContext(event, empty, empty);
  PrintBadEvent(event, "unsupported event");
}

void EventPrinter::OnUnparsableEvent(const EVENT_TRACE* event) {
  base::StringPiece empty;
  PrintEventContext(event, empty, empty);
  PrintBadEvent(event, "parse error");
}

void EventPrinter::OnFileHeader(const EVENT_TRACE* event,
                                const TRACE_LOGFILE_HEADER* header) {
  base::StringPiece empty;
  PrintEventContext(event, empty, empty);

  *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." << std::endl;
}

void EventPrinter::OnLogMessage(const EVENT_TRACE* event,
                                logging::LogSeverity severity,
                                const base::StringPiece& message) {
  std::ostringstream level_stream;
  WriteSeverityToStream(severity, &level_stream);
  PrintEventContext(event, level_stream.str(), base::StringPiece());
  *out_ << message << std::endl;
}

void EventPrinter::OnLogMessageFull(const EVENT_TRACE* event,
                                    logging::LogSeverity severity,
                                    DWORD stack_depth,
                                    const intptr_t* backtrace,
                                    int line,
                                    const base::StringPiece& file,
                                    const base::StringPiece& message) {
  std::ostringstream level_stream;
  std::ostringstream location_stream;
  WriteSeverityToStream(severity, &level_stream);
  WriteLocationToStream(file, line, &location_stream);
  PrintEventContext(event, level_stream.str(), location_stream.str());
  *out_ << message << std::endl;
}

void EventPrinter::OnTraceEvent(const EVENT_TRACE* event,
                                const base::StringPiece& name,
                                char type,
                                intptr_t id,
                                const base::StringPiece& extra,
                                DWORD stack_depth,
                                const intptr_t* backtrace) {
  PrintEventContext(event, GetTraceTypeString(type), base::StringPiece());
  *out_ << name << " (id=0x" << std::hex << id << std::dec << ") " << extra
        << std::endl;
}

}  // namespace

void logging_win::PrintLogFile(const FilePath& log_file,
                               std::ostream* out) {
  EventPrinter printer(out);
  logging_win::ReadLogFile(log_file, &printer);
}