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