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_FATAL:
42      *out << "FATAL";
43      break;
44    default:
45      if (severity < 0)
46        *out << "VERBOSE" << -severity;
47      else
48        NOTREACHED();
49      break;
50  }
51}
52
53// TODO(grt) This duplicates private behavior in base/logging.cc's
54// LogMessage::Init.  That behavior should be exposed and used here (possibly
55// by moving this function to logging.cc and publishing it in logging.h with
56// BASE_EXPORT).
57void WriteLocationToStream(const base::StringPiece& file,
58                           int line,
59                           std::ostream* out) {
60  base::StringPiece filename(file);
61  size_t last_slash_pos = filename.find_last_of("\\/");
62  if (last_slash_pos != base::StringPiece::npos)
63    filename.remove_prefix(last_slash_pos + 1);
64
65  *out << filename << '(' << line << ')';
66}
67
68// Returns a pretty string for the trace event types that appear in ETW logs.
69const char* GetTraceTypeString(char event_type) {
70  switch (event_type) {
71    case TRACE_EVENT_PHASE_BEGIN:
72      return "BEGIN";
73      break;
74    case TRACE_EVENT_PHASE_END:
75      return "END";
76      break;
77    case TRACE_EVENT_PHASE_INSTANT:
78      return "INSTANT";
79      break;
80    default:
81      NOTREACHED();
82      return "";
83      break;
84  }
85}
86
87class EventPrinter : public logging_win::LogFileDelegate {
88 public:
89  explicit EventPrinter(std::ostream* out);
90  virtual ~EventPrinter();
91
92  virtual void OnUnknownEvent(const EVENT_TRACE* event) OVERRIDE;
93
94  virtual void OnUnparsableEvent(const EVENT_TRACE* event) OVERRIDE;
95
96  virtual void OnFileHeader(const EVENT_TRACE* event,
97                            const TRACE_LOGFILE_HEADER* header) OVERRIDE;
98
99  virtual void OnLogMessage(const EVENT_TRACE* event,
100                            logging::LogSeverity severity,
101                            const base::StringPiece& message) OVERRIDE;
102
103  virtual void OnLogMessageFull(const EVENT_TRACE* event,
104                                logging::LogSeverity severity,
105                                DWORD stack_depth,
106                                const intptr_t* backtrace,
107                                int line,
108                                const base::StringPiece& file,
109                                const base::StringPiece& message) OVERRIDE;
110
111  virtual void OnTraceEvent(const EVENT_TRACE* event,
112                            const base::StringPiece& name,
113                            char type,
114                            intptr_t id,
115                            const base::StringPiece& extra,
116                            DWORD stack_depth,
117                            const intptr_t* backtrace) OVERRIDE;
118
119 private:
120  void PrintTimeStamp(LARGE_INTEGER time_stamp);
121  void PrintEventContext(const EVENT_TRACE* event,
122                         const base::StringPiece& level,
123                         const base::StringPiece& context);
124  void PrintBadEvent(const EVENT_TRACE* event, const base::StringPiece& error);
125
126  std::ostream* out_;
127  DISALLOW_COPY_AND_ASSIGN(EventPrinter);
128};
129
130EventPrinter::EventPrinter(std::ostream* out)
131    : out_(out) {
132}
133
134EventPrinter::~EventPrinter() {
135}
136
137void EventPrinter::PrintTimeStamp(LARGE_INTEGER time_stamp) {
138  FILETIME event_time = {};
139  base::Time::Exploded time_exploded = {};
140  event_time.dwLowDateTime = time_stamp.LowPart;
141  event_time.dwHighDateTime = time_stamp.HighPart;
142  base::Time::FromFileTime(event_time).LocalExplode(&time_exploded);
143
144  *out_ << std::setfill('0')
145        << std::setw(2) << time_exploded.month
146        << std::setw(2) << time_exploded.day_of_month
147        << '/'
148        << std::setw(2) << time_exploded.hour
149        << std::setw(2) << time_exploded.minute
150        << std::setw(2) << time_exploded.second
151        << '.'
152        << std::setw(3) << time_exploded.millisecond;
153}
154
155// Prints the context info at the start of each line: pid, tid, time, etc.
156void EventPrinter::PrintEventContext(const EVENT_TRACE* event,
157                                     const base::StringPiece& level,
158                                     const base::StringPiece& context) {
159  *out_ << '[' << event->Header.ProcessId << ':'
160        << event->Header.ThreadId << ':';
161  PrintTimeStamp(event->Header.TimeStamp);
162  if (!level.empty())
163    *out_ << ':' << level;
164  if (!context.empty())
165    *out_ << ':' << context;
166  *out_ << "] ";
167}
168
169// Prints a useful message for events that can't be otherwise printed.
170void EventPrinter::PrintBadEvent(const EVENT_TRACE* event,
171                                 const base::StringPiece& error) {
172  wchar_t guid[64];
173  StringFromGUID2(event->Header.Guid, &guid[0], arraysize(guid));
174  *out_ << error << " (class=" << guid << ", type="
175       << static_cast<int>(event->Header.Class.Type) << ")";
176}
177
178void EventPrinter::OnUnknownEvent(const EVENT_TRACE* event) {
179  base::StringPiece empty;
180  PrintEventContext(event, empty, empty);
181  PrintBadEvent(event, "unsupported event");
182}
183
184void EventPrinter::OnUnparsableEvent(const EVENT_TRACE* event) {
185  base::StringPiece empty;
186  PrintEventContext(event, empty, empty);
187  PrintBadEvent(event, "parse error");
188}
189
190void EventPrinter::OnFileHeader(const EVENT_TRACE* event,
191                                const TRACE_LOGFILE_HEADER* header) {
192  base::StringPiece empty;
193  PrintEventContext(event, empty, empty);
194
195  *out_ << "Log captured from Windows "
196        << static_cast<int>(header->VersionDetail.MajorVersion) << '.'
197        << static_cast<int>(header->VersionDetail.MinorVersion) << '.'
198        << static_cast<int>(header->VersionDetail.SubVersion) << '.'
199        << static_cast<int>(header->VersionDetail.SubMinorVersion)
200        << ".  " << header->EventsLost << " events lost, "
201        << header->BuffersLost << " buffers lost." << std::endl;
202}
203
204void EventPrinter::OnLogMessage(const EVENT_TRACE* event,
205                                logging::LogSeverity severity,
206                                const base::StringPiece& message) {
207  std::ostringstream level_stream;
208  WriteSeverityToStream(severity, &level_stream);
209  PrintEventContext(event, level_stream.str(), base::StringPiece());
210  *out_ << message << std::endl;
211}
212
213void EventPrinter::OnLogMessageFull(const EVENT_TRACE* event,
214                                    logging::LogSeverity severity,
215                                    DWORD stack_depth,
216                                    const intptr_t* backtrace,
217                                    int line,
218                                    const base::StringPiece& file,
219                                    const base::StringPiece& message) {
220  std::ostringstream level_stream;
221  std::ostringstream location_stream;
222  WriteSeverityToStream(severity, &level_stream);
223  WriteLocationToStream(file, line, &location_stream);
224  PrintEventContext(event, level_stream.str(), location_stream.str());
225  *out_ << message << std::endl;
226}
227
228void EventPrinter::OnTraceEvent(const EVENT_TRACE* event,
229                                const base::StringPiece& name,
230                                char type,
231                                intptr_t id,
232                                const base::StringPiece& extra,
233                                DWORD stack_depth,
234                                const intptr_t* backtrace) {
235  PrintEventContext(event, GetTraceTypeString(type), base::StringPiece());
236  *out_ << name << " (id=0x" << std::hex << id << std::dec << ") " << extra
237        << std::endl;
238}
239
240}  // namespace
241
242void logging_win::PrintLogFile(const base::FilePath& log_file,
243                               std::ostream* out) {
244  EventPrinter printer(out);
245  logging_win::ReadLogFile(log_file, &printer);
246}
247