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