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
24namespace {
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).
30void 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).
60void 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.
72const 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
90class 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
133EventPrinter::EventPrinter(std::ostream* out)
134    : out_(out) {
135}
136
137EventPrinter::~EventPrinter() {
138}
139
140void 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.
159void 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.
173void 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
181void EventPrinter::OnUnknownEvent(const EVENT_TRACE* event) {
182  base::StringPiece empty;
183  PrintEventContext(event, empty, empty);
184  PrintBadEvent(event, "unsupported event");
185}
186
187void EventPrinter::OnUnparsableEvent(const EVENT_TRACE* event) {
188  base::StringPiece empty;
189  PrintEventContext(event, empty, empty);
190  PrintBadEvent(event, "parse error");
191}
192
193void 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
207void 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
216void 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
231void 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
245void 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