// 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 #include #include #include #include #include #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(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(header->VersionDetail.MajorVersion) << '.' << static_cast(header->VersionDetail.MinorVersion) << '.' << static_cast(header->VersionDetail.SubVersion) << '.' << static_cast(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); }