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).
WriteSeverityToStream(logging::LogSeverity severity,std::ostream * out)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).
WriteLocationToStream(const base::StringPiece & file,int line,std::ostream * out)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.
GetTraceTypeString(char event_type)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
EventPrinter(std::ostream * out)133 EventPrinter::EventPrinter(std::ostream* out)
134 : out_(out) {
135 }
136
~EventPrinter()137 EventPrinter::~EventPrinter() {
138 }
139
PrintTimeStamp(LARGE_INTEGER time_stamp)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.
PrintEventContext(const EVENT_TRACE * event,const base::StringPiece & level,const base::StringPiece & context)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.
PrintBadEvent(const EVENT_TRACE * event,const base::StringPiece & error)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
OnUnknownEvent(const EVENT_TRACE * event)181 void EventPrinter::OnUnknownEvent(const EVENT_TRACE* event) {
182 base::StringPiece empty;
183 PrintEventContext(event, empty, empty);
184 PrintBadEvent(event, "unsupported event");
185 }
186
OnUnparsableEvent(const EVENT_TRACE * event)187 void EventPrinter::OnUnparsableEvent(const EVENT_TRACE* event) {
188 base::StringPiece empty;
189 PrintEventContext(event, empty, empty);
190 PrintBadEvent(event, "parse error");
191 }
192
OnFileHeader(const EVENT_TRACE * event,const TRACE_LOGFILE_HEADER * header)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
OnLogMessage(const EVENT_TRACE * event,logging::LogSeverity severity,const base::StringPiece & message)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
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)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
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)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
PrintLogFile(const base::FilePath & log_file,std::ostream * out)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