Home | History | Annotate | Download | only in win 
      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_reader.h"
      6 
      7 #include "base/debug/trace_event_win.h"
      8 #include "base/files/file_path.h"
      9 #include "base/lazy_instance.h"
     10 #include "base/logging_win.h"
     11 #include "base/synchronization/lock.h"
     12 #include "base/win/event_trace_consumer.h"
     13 #include "chrome/test/logging/win/mof_data_parser.h"
     14 
     15 namespace logging_win {
     16 
     17 namespace {
     18 
     19 // TODO(grt) This reverses a mapping produced by base/logging_win.cc's
     20 // LogEventProvider::LogMessage.  LogEventProvider should expose a way to map an
     21 // event level back to a log severity.
     22 logging::LogSeverity EventLevelToSeverity(uint8 level) {
     23   switch (level) {
     24   case TRACE_LEVEL_NONE:
     25     NOTREACHED();
     26     return logging::LOG_ERROR;
     27   case TRACE_LEVEL_FATAL:
     28     return logging::LOG_FATAL;
     29   case TRACE_LEVEL_ERROR:
     30     return logging::LOG_ERROR;
     31   case TRACE_LEVEL_WARNING:
     32     return logging::LOG_WARNING;
     33   case TRACE_LEVEL_INFORMATION:
     34     return logging::LOG_INFO;
     35   default:
     36     // Trace levels above information correspond to negative severity levels,
     37     // which are used for VLOG verbosity levels.
     38     return TRACE_LEVEL_INFORMATION - level;
     39   }
     40 }
     41 
     42 // TODO(grt) This reverses a mapping produced by base/debug/trace_event_win.cc's
     43 // TraceEventETWProvider::TraceEvent.  TraceEventETWProvider should expose a way
     44 // to map an event type back to a trace type.
     45 char EventTypeToTraceType(uint8 event_type) {
     46   switch (event_type) {
     47     case base::debug::kTraceEventTypeBegin:
     48       return TRACE_EVENT_PHASE_BEGIN;
     49       break;
     50     case base::debug::kTraceEventTypeEnd:
     51       return TRACE_EVENT_PHASE_END;
     52       break;
     53     case base::debug::kTraceEventTypeInstant:
     54       return TRACE_EVENT_PHASE_INSTANT;
     55       break;
     56     default:
     57       NOTREACHED();
     58       return '\0';
     59       break;
     60   }
     61 }
     62 
     63 class LogFileReader {
     64  public:
     65   explicit LogFileReader(LogFileDelegate* delegate);
     66   ~LogFileReader();
     67 
     68   static void ReadFile(const base::FilePath& log_file,
     69                        LogFileDelegate* delegate);
     70 
     71  private:
     72   // An implementation of a trace consumer that delegates to a given (at
     73   // compile-time) event processing function.
     74   template<void (*ProcessEventFn)(EVENT_TRACE*)>
     75   class TraceConsumer
     76       : public base::win::EtwTraceConsumerBase<TraceConsumer<ProcessEventFn> > {
     77    public:
     78     TraceConsumer() { }
     79     static void ProcessEvent(EVENT_TRACE* event) { (*ProcessEventFn)(event); }
     80    private:
     81     DISALLOW_COPY_AND_ASSIGN(TraceConsumer);
     82   };
     83 
     84   // Delegates to DispatchEvent() of the current LogDumper instance.
     85   static void ProcessEvent(EVENT_TRACE* event);
     86 
     87   // Handlers for the supported event types.
     88   bool OnLogMessageEvent(const EVENT_TRACE* event);
     89   bool OnLogMessageFullEvent(const EVENT_TRACE* event);
     90   bool OnTraceEvent(const EVENT_TRACE* event);
     91   bool OnFileHeader(const EVENT_TRACE* event);
     92 
     93   // Parses an event and passes it along to the delegate for processing.
     94   void DispatchEvent(const EVENT_TRACE* event);
     95 
     96   // Reads the file using a trace consumer.  |ProcessEvent| will be invoked for
     97   // each event in the file.
     98   void Read(const base::FilePath& log_file);
     99 
    100   // Protects use of the class; only one instance may be live at a time.
    101   static base::LazyInstance<base::Lock>::Leaky reader_lock_;
    102 
    103   // The currently living instance.
    104   static LogFileReader* instance_;
    105 
    106   // The delegate to be notified of events.
    107   LogFileDelegate* delegate_;
    108 };
    109 
    110 // static
    111 base::LazyInstance<base::Lock>::Leaky LogFileReader::reader_lock_ =
    112     LAZY_INSTANCE_INITIALIZER;
    113 
    114 // static
    115 LogFileReader* LogFileReader::instance_ = NULL;
    116 
    117 LogFileReader::LogFileReader(LogFileDelegate* delegate)
    118     : delegate_(delegate) {
    119   DCHECK(instance_ == NULL);
    120   DCHECK(delegate != NULL);
    121   instance_ = this;
    122 }
    123 
    124 LogFileReader::~LogFileReader() {
    125   DCHECK_EQ(instance_, this);
    126   instance_ = NULL;
    127 }
    128 
    129 // static
    130 void LogFileReader::ProcessEvent(EVENT_TRACE* event) {
    131   if (instance_ != NULL)
    132     instance_->DispatchEvent(event);
    133 }
    134 
    135 bool LogFileReader::OnLogMessageEvent(const EVENT_TRACE* event) {
    136   base::StringPiece message;
    137   MofDataParser parser(event);
    138 
    139   // See LogEventProvider::LogMessage where ENABLE_LOG_MESSAGE_ONLY is set.
    140   if (parser.ReadString(&message) && parser.empty()) {
    141     delegate_->OnLogMessage(event,
    142                             EventLevelToSeverity(event->Header.Class.Level),
    143                             message);
    144     return true;
    145   }
    146   return false;
    147 }
    148 
    149 bool LogFileReader::OnLogMessageFullEvent(const EVENT_TRACE* event) {
    150   DWORD stack_depth = 0;
    151   const intptr_t* backtrace = NULL;
    152   int line = 0;
    153   base::StringPiece file;
    154   base::StringPiece message;
    155   MofDataParser parser(event);
    156 
    157   // See LogEventProvider::LogMessage where ENABLE_LOG_MESSAGE_ONLY is not set.
    158   if (parser.ReadDWORD(&stack_depth) &&
    159       parser.ReadPointerArray(stack_depth, &backtrace) &&
    160       parser.ReadInt(&line) &&
    161       parser.ReadString(&file) &&
    162       parser.ReadString(&message) &&
    163       parser.empty()) {
    164     delegate_->OnLogMessageFull(event,
    165         EventLevelToSeverity(event->Header.Class.Level), stack_depth, backtrace,
    166         line, file, message);
    167     return true;
    168   }
    169   return false;
    170 }
    171 
    172 bool LogFileReader::OnTraceEvent(const EVENT_TRACE* event) {
    173   MofDataParser parser(event);
    174   base::StringPiece name;
    175   intptr_t id = 0;
    176   base::StringPiece extra;
    177   DWORD stack_depth = 0;
    178   const intptr_t* backtrace = NULL;
    179 
    180   // See TraceEventETWProvider::TraceEvent.
    181   if (parser.ReadString(&name) &&
    182       parser.ReadPointer(&id) &&
    183       parser.ReadString(&extra) &&
    184       (parser.empty() ||
    185        parser.ReadDWORD(&stack_depth) &&
    186        parser.ReadPointerArray(stack_depth, &backtrace) &&
    187        parser.empty())) {
    188     delegate_->OnTraceEvent(event, name,
    189         EventTypeToTraceType(event->Header.Class.Type), id, extra, stack_depth,
    190         backtrace);
    191     return true;
    192   }
    193   return false;
    194 }
    195 
    196 bool LogFileReader::OnFileHeader(const EVENT_TRACE* event) {
    197   MofDataParser parser(event);
    198   const TRACE_LOGFILE_HEADER* header = NULL;
    199 
    200   if (parser.ReadStructure(&header)) {
    201     delegate_->OnFileHeader(event, header);
    202     return true;
    203   }
    204   return false;
    205 }
    206 
    207 void LogFileReader::DispatchEvent(const EVENT_TRACE* event) {
    208   bool parsed = true;
    209 
    210   if (IsEqualGUID(event->Header.Guid, logging::kLogEventId)) {
    211     if (event->Header.Class.Type == logging::LOG_MESSAGE)
    212       parsed = OnLogMessageEvent(event);
    213     else if (event->Header.Class.Type == logging::LOG_MESSAGE_FULL)
    214       parsed = OnLogMessageFullEvent(event);
    215   } else if (IsEqualGUID(event->Header.Guid, base::debug::kTraceEventClass32)) {
    216     parsed = OnTraceEvent(event);
    217   } else if (IsEqualGUID(event->Header.Guid, EventTraceGuid)) {
    218     parsed = OnFileHeader(event);
    219   } else {
    220     DCHECK(parsed);
    221     delegate_->OnUnknownEvent(event);
    222   }
    223   if (!parsed)
    224     delegate_->OnUnparsableEvent(event);
    225 }
    226 
    227 void LogFileReader::Read(const base::FilePath& log_file) {
    228   TraceConsumer<&ProcessEvent> consumer;
    229   HRESULT hr = S_OK;
    230 
    231   hr = consumer.OpenFileSession(log_file.value().c_str());
    232   if (FAILED(hr)) {
    233     LOG(ERROR) << "Failed to open session for log file " << log_file.value()
    234                << "; hr=" << std::hex << hr;
    235   } else {
    236     consumer.Consume();
    237     consumer.Close();
    238   }
    239 }
    240 
    241 // static
    242 void LogFileReader::ReadFile(const base::FilePath& log_file,
    243                              LogFileDelegate* delegate) {
    244   base::AutoLock lock(reader_lock_.Get());
    245 
    246   LogFileReader(delegate).Read(log_file);
    247 }
    248 
    249 }  // namespace
    250 
    251 LogFileDelegate::LogFileDelegate() {
    252 }
    253 
    254 LogFileDelegate::~LogFileDelegate() {
    255 }
    256 
    257 void ReadLogFile(const base::FilePath& log_file, LogFileDelegate* delegate) {
    258   DCHECK(delegate);
    259   LogFileReader::ReadFile(log_file, delegate);
    260 }
    261 
    262 }  // logging_win
    263