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 } 247
