chrome/test/logging/win/log_file_printer.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "chrome/test/logging/win/log_file_printer.h"
   6
   7 #include <windows.h>
   8 #include <objbase.h>
   9
  10 #include <iomanip>
  11 #include <ios>
  12 #include <ostream>
  13 #include <sstream>
  14
  15 #include "base/basictypes.h"
  16 #include "base/compiler_specific.h"
  17 #include "base/debug/trace_event.h"
  18 #include "base/logging.h"
  19 #include "base/strings/string_number_conversions.h"
  20 #include "base/strings/string_piece.h"
  21 #include "base/time/time.h"
  22 #include "chrome/test/logging/win/log_file_reader.h"
  23
  24 namespace {
  25
  26 // TODO(grt) This duplicates private behavior in base/logging.cc's
  27 // LogMessage::Init.  That behavior should be exposed and used here (possibly
  28 // by moving this function to logging.cc, making it use log_severity_names, and
  29 // publishing it in logging.h with BASE_EXPORT).
  30 void WriteSeverityToStream(logging::LogSeverity severity, std::ostream* out) {
  31   switch (severity) {
  32     case logging::LOG_INFO:
  33       *out << "INFO";
  34       break;
  35     case logging::LOG_WARNING:
  36       *out << "WARNING";
  37       break;
  38     case logging::LOG_ERROR:
  39       *out << "ERROR";
  40       break;
  41     case logging::LOG_ERROR_REPORT:
  42       *out << "ERROR_REPORT";
  43       break;
  44     case logging::LOG_FATAL:
  45       *out << "FATAL";
  46       break;
  47     default:
  48       if (severity < 0)
  49         *out << "VERBOSE" << -severity;
  50       else
  51         NOTREACHED();
  52       break;
  53   }
  54 }
  55
  56 // TODO(grt) This duplicates private behavior in base/logging.cc's
  57 // LogMessage::Init.  That behavior should be exposed and used here (possibly
  58 // by moving this function to logging.cc and publishing it in logging.h with
  59 // BASE_EXPORT).
  60 void WriteLocationToStream(const base::StringPiece& file,
  61                            int line,
  62                            std::ostream* out) {
  63   base::StringPiece filename(file);
  64   size_t last_slash_pos = filename.find_last_of("\\/");
  65   if (last_slash_pos != base::StringPiece::npos)
  66     filename.remove_prefix(last_slash_pos + 1);
  67
  68   *out << filename << '(' << line << ')';
  69 }
  70
  71 // Returns a pretty string for the trace event types that appear in ETW logs.
  72 const char* GetTraceTypeString(char event_type) {
  73   switch (event_type) {
  74     case TRACE_EVENT_PHASE_BEGIN:
  75       return "BEGIN";
  76       break;
  77     case TRACE_EVENT_PHASE_END:
  78       return "END";
  79       break;
  80     case TRACE_EVENT_PHASE_INSTANT:
  81       return "INSTANT";
  82       break;
  83     default:
  84       NOTREACHED();
  85       return "";
  86       break;
  87   }
  88 }
  89
  90 class EventPrinter : public logging_win::LogFileDelegate {
  91  public:
  92   explicit EventPrinter(std::ostream* out);
  93   virtual ~EventPrinter();
  94
  95   virtual void OnUnknownEvent(const EVENT_TRACE* event) OVERRIDE;
  96
  97   virtual void OnUnparsableEvent(const EVENT_TRACE* event) OVERRIDE;
  98
  99   virtual void OnFileHeader(const EVENT_TRACE* event,
 100                             const TRACE_LOGFILE_HEADER* header) OVERRIDE;
 101
 102   virtual void OnLogMessage(const EVENT_TRACE* event,
 103                             logging::LogSeverity severity,
 104                             const base::StringPiece& message) OVERRIDE;
 105
 106   virtual void OnLogMessageFull(const EVENT_TRACE* event,
 107                                 logging::LogSeverity severity,
 108                                 DWORD stack_depth,
 109                                 const intptr_t* backtrace,
 110                                 int line,
 111                                 const base::StringPiece& file,
 112                                 const base::StringPiece& message) OVERRIDE;
 113
 114   virtual void OnTraceEvent(const EVENT_TRACE* event,
 115                             const base::StringPiece& name,
 116                             char type,
 117                             intptr_t id,
 118                             const base::StringPiece& extra,
 119                             DWORD stack_depth,
 120                             const intptr_t* backtrace) OVERRIDE;
 121
 122  private:
 123   void PrintTimeStamp(LARGE_INTEGER time_stamp);
 124   void PrintEventContext(const EVENT_TRACE* event,
 125                          const base::StringPiece& level,
 126                          const base::StringPiece& context);
 127   void PrintBadEvent(const EVENT_TRACE* event, const base::StringPiece& error);
 128
 129   std::ostream* out_;
 130   DISALLOW_COPY_AND_ASSIGN(EventPrinter);
 131 };
 132
 133 EventPrinter::EventPrinter(std::ostream* out)
 134     : out_(out) {
 135 }
 136
 137 EventPrinter::~EventPrinter() {
 138 }
 139
 140 void EventPrinter::PrintTimeStamp(LARGE_INTEGER time_stamp) {
 141   FILETIME event_time = {};
 142   base::Time::Exploded time_exploded = {};
 143   event_time.dwLowDateTime = time_stamp.LowPart;
 144   event_time.dwHighDateTime = time_stamp.HighPart;
 145   base::Time::FromFileTime(event_time).LocalExplode(&time_exploded);
 146
 147   *out_ << std::setfill('0')
 148         << std::setw(2) << time_exploded.month
 149         << std::setw(2) << time_exploded.day_of_month
 150         << '/'
 151         << std::setw(2) << time_exploded.hour
 152         << std::setw(2) << time_exploded.minute
 153         << std::setw(2) << time_exploded.second
 154         << '.'
 155         << std::setw(3) << time_exploded.millisecond;
 156 }
 157
 158 // Prints the context info at the start of each line: pid, tid, time, etc.
 159 void EventPrinter::PrintEventContext(const EVENT_TRACE* event,
 160                                      const base::StringPiece& level,
 161                                      const base::StringPiece& context) {
 162   *out_ << '[' << event->Header.ProcessId << ':'
 163         << event->Header.ThreadId << ':';
 164   PrintTimeStamp(event->Header.TimeStamp);
 165   if (!level.empty())
 166     *out_ << ':' << level;
 167   if (!context.empty())
 168     *out_ << ':' << context;
 169   *out_ << "] ";
 170 }
 171
 172 // Prints a useful message for events that can't be otherwise printed.
 173 void EventPrinter::PrintBadEvent(const EVENT_TRACE* event,
 174                                  const base::StringPiece& error) {
 175   wchar_t guid[64];
 176   StringFromGUID2(event->Header.Guid, &guid[0], arraysize(guid));
 177   *out_ << error << " (class=" << guid << ", type="
 178        << static_cast<int>(event->Header.Class.Type) << ")";
 179 }
 180
 181 void EventPrinter::OnUnknownEvent(const EVENT_TRACE* event) {
 182   base::StringPiece empty;
 183   PrintEventContext(event, empty, empty);
 184   PrintBadEvent(event, "unsupported event");
 185 }
 186
 187 void EventPrinter::OnUnparsableEvent(const EVENT_TRACE* event) {
 188   base::StringPiece empty;
 189   PrintEventContext(event, empty, empty);
 190   PrintBadEvent(event, "parse error");
 191 }
 192
 193 void EventPrinter::OnFileHeader(const EVENT_TRACE* event,
 194                                 const TRACE_LOGFILE_HEADER* header) {
 195   base::StringPiece empty;
 196   PrintEventContext(event, empty, empty);
 197
 198   *out_ << "Log captured from Windows "
 199         << static_cast<int>(header->VersionDetail.MajorVersion) << '.'
 200         << static_cast<int>(header->VersionDetail.MinorVersion) << '.'
 201         << static_cast<int>(header->VersionDetail.SubVersion) << '.'
 202         << static_cast<int>(header->VersionDetail.SubMinorVersion)
 203         << ".  " << header->EventsLost << " events lost, "
 204         << header->BuffersLost << " buffers lost." << std::endl;
 205 }
 206
 207 void EventPrinter::OnLogMessage(const EVENT_TRACE* event,
 208                                 logging::LogSeverity severity,
 209                                 const base::StringPiece& message) {
 210   std::ostringstream level_stream;
 211   WriteSeverityToStream(severity, &level_stream);
 212   PrintEventContext(event, level_stream.str(), base::StringPiece());
 213   *out_ << message << std::endl;
 214 }
 215
 216 void EventPrinter::OnLogMessageFull(const EVENT_TRACE* event,
 217                                     logging::LogSeverity severity,
 218                                     DWORD stack_depth,
 219                                     const intptr_t* backtrace,
 220                                     int line,
 221                                     const base::StringPiece& file,
 222                                     const base::StringPiece& message) {
 223   std::ostringstream level_stream;
 224   std::ostringstream location_stream;
 225   WriteSeverityToStream(severity, &level_stream);
 226   WriteLocationToStream(file, line, &location_stream);
 227   PrintEventContext(event, level_stream.str(), location_stream.str());
 228   *out_ << message << std::endl;
 229 }
 230
 231 void EventPrinter::OnTraceEvent(const EVENT_TRACE* event,
 232                                 const base::StringPiece& name,
 233                                 char type,
 234                                 intptr_t id,
 235                                 const base::StringPiece& extra,
 236                                 DWORD stack_depth,
 237                                 const intptr_t* backtrace) {
 238   PrintEventContext(event, GetTraceTypeString(type), base::StringPiece());
 239   *out_ << name << " (id=0x" << std::hex << id << std::dec << ") " << extra
 240         << std::endl;
 241 }
 242
 243 }  // namespace
 244
 245 void logging_win::PrintLogFile(const base::FilePath& log_file,
 246                                std::ostream* out) {
 247   EventPrinter printer(out);
 248   logging_win::ReadLogFile(log_file, &printer);
 249 }