• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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