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/file_logger.h"
      6 
      7 #include <windows.h>
      8 #include <guiddef.h>
      9 #include <objbase.h>
     10 
     11 #include <ios>
     12 
     13 #include "base/debug/trace_event_win.h"
     14 #include "base/files/file_path.h"
     15 #include "base/logging.h"
     16 #include "base/logging_win.h"
     17 #include "base/strings/string16.h"
     18 #include "base/strings/utf_string_conversions.h"
     19 #include "base/win/event_trace_consumer.h"
     20 #include "base/win/registry.h"
     21 
     22 namespace logging_win {
     23 
     24 namespace {
     25 
     26 const wchar_t kChromeTestSession[] = L"chrome_tests";
     27 
     28 // From chrome_tab.cc: {0562BFC3-2550-45b4-BD8E-A310583D3A6F}
     29 const GUID kChromeFrameProvider =
     30     { 0x562bfc3, 0x2550, 0x45b4,
     31         { 0xbd, 0x8e, 0xa3, 0x10, 0x58, 0x3d, 0x3a, 0x6f } };
     32 
     33 // From chrome/common/logging_chrome.cc: {7FE69228-633E-4f06-80C1-527FEA23E3A7}
     34 const GUID kChromeTraceProviderName =
     35     { 0x7fe69228, 0x633e, 0x4f06,
     36         { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } };
     37 
     38 // {81729947-CD2A-49e6-8885-785429F339F5}
     39 const GUID kChromeTestsProvider =
     40     { 0x81729947, 0xcd2a, 0x49e6,
     41         { 0x88, 0x85, 0x78, 0x54, 0x29, 0xf3, 0x39, 0xf5 } };
     42 
     43 // The configurations for the supported providers.  This must be in sync with
     44 // FileLogger::EventProviderBits.
     45 const struct {
     46   const GUID* provider_name;
     47   uint8 level;
     48   uint32 flags;
     49 } kProviders[] = {
     50   { &kChromeTraceProviderName, 255, 0 },
     51   { &kChromeFrameProvider, 255, 0 },
     52   { &kChromeTestsProvider, 255, 0 },
     53   { &base::debug::kChromeTraceProviderName, 255, 0 }
     54 };
     55 
     56 COMPILE_ASSERT((1 << arraysize(kProviders)) - 1 ==
     57                    FileLogger::kAllEventProviders,
     58                size_of_kProviders_is_inconsistent_with_kAllEventProviders);
     59 
     60 }  // namespace
     61 
     62 bool FileLogger::is_initialized_ = false;
     63 
     64 FileLogger::FileLogger()
     65     : event_provider_mask_() {
     66 }
     67 
     68 FileLogger::~FileLogger() {
     69   if (is_logging()) {
     70     LOG(ERROR)
     71       << __FUNCTION__ << " don't forget to call FileLogger::StopLogging()";
     72     StopLogging();
     73   }
     74 
     75   is_initialized_ = false;
     76 }
     77 
     78 // Returns false if all providers could not be enabled.  A log message is
     79 // produced for each provider that could not be enabled.
     80 bool FileLogger::EnableProviders() {
     81   // Default to false if there's at least one provider.
     82   bool result = (event_provider_mask_ == 0);
     83 
     84   // Generate ETW log events for this test binary.  Log messages at and above
     85   // logging::GetMinLogLevel() will continue to go to stderr as well.  This
     86   // leads to double logging in case of test failures: each LOG statement at
     87   // or above the min level will go to stderr during test execution, and then
     88   // all events logged to the file session will be dumped again.  If this
     89   // turns out to be an issue, one could call logging::SetMinLogLevel(INT_MAX)
     90   // here (stashing away the previous min log level to be restored in
     91   // DisableProviders) to suppress stderr logging during test execution.  Then
     92   // those events in the file that were logged at/above the old min level from
     93   // the test binary could be dumped to stderr if there were no failures.
     94   if (event_provider_mask_ & CHROME_TESTS_LOG_PROVIDER)
     95     logging::LogEventProvider::Initialize(kChromeTestsProvider);
     96 
     97   HRESULT hr = S_OK;
     98   for (size_t i = 0; i < arraysize(kProviders); ++i) {
     99     if (event_provider_mask_ & (1 << i)) {
    100       hr = controller_.EnableProvider(*kProviders[i].provider_name,
    101                                       kProviders[i].level,
    102                                       kProviders[i].flags);
    103       if (FAILED(hr)) {
    104         LOG(ERROR) << "Failed to enable event provider " << i
    105                    << "; hr=" << std::hex << hr;
    106       } else {
    107         result = true;
    108       }
    109     }
    110   }
    111 
    112   return result;
    113 }
    114 
    115 void FileLogger::DisableProviders() {
    116   HRESULT hr = S_OK;
    117   for (size_t i = 0; i < arraysize(kProviders); ++i) {
    118     if (event_provider_mask_ & (1 << i)) {
    119       hr = controller_.DisableProvider(*kProviders[i].provider_name);
    120       LOG_IF(ERROR, FAILED(hr)) << "Failed to disable event provider "
    121                                 << i << "; hr=" << std::hex << hr;
    122     }
    123   }
    124 
    125   if (event_provider_mask_ & CHROME_TESTS_LOG_PROVIDER)
    126     logging::LogEventProvider::Uninitialize();
    127 }
    128 
    129 void FileLogger::Initialize() {
    130   Initialize(kAllEventProviders);
    131 }
    132 
    133 void FileLogger::Initialize(uint32 event_provider_mask) {
    134   CHECK(!is_initialized_);
    135 
    136   // Stop a previous session that wasn't shut down properly.
    137   base::win::EtwTraceProperties ignore;
    138   HRESULT hr = base::win::EtwTraceController::Stop(kChromeTestSession,
    139                                                    &ignore);
    140   LOG_IF(ERROR, FAILED(hr) &&
    141              hr != HRESULT_FROM_WIN32(ERROR_WMI_INSTANCE_NOT_FOUND))
    142       << "Failed to stop a previous trace session; hr=" << std::hex << hr;
    143 
    144   event_provider_mask_ = event_provider_mask;
    145 
    146   is_initialized_ = true;
    147 }
    148 
    149 bool FileLogger::StartLogging(const base::FilePath& log_file) {
    150   HRESULT hr =
    151       controller_.StartFileSession(kChromeTestSession,
    152                                    log_file.value().c_str(), false);
    153   if (SUCCEEDED(hr)) {
    154     // Ignore the return value here in the hopes that at least one provider was
    155     // enabled.
    156     if (!EnableProviders()) {
    157       LOG(ERROR) << "Failed to enable any provider.";
    158       controller_.Stop(NULL);
    159       return false;
    160     }
    161   } else {
    162     if (hr == HRESULT_FROM_WIN32(ERROR_ACCESS_DENIED)) {
    163       LOG(WARNING) << "Access denied while trying to start trace session. "
    164                       "This is expected when not running as an administrator.";
    165     } else {
    166       LOG(ERROR) << "Failed to start trace session to file " << log_file.value()
    167                  << "; hr=" << std::hex << hr;
    168     }
    169     return false;
    170   }
    171   return true;
    172 }
    173 
    174 void FileLogger::StopLogging() {
    175   HRESULT hr = S_OK;
    176 
    177   DisableProviders();
    178 
    179   hr = controller_.Flush(NULL);
    180   LOG_IF(ERROR, FAILED(hr))
    181       << "Failed to flush events; hr=" << std::hex << hr;
    182   hr = controller_.Stop(NULL);
    183   LOG_IF(ERROR, FAILED(hr))
    184       << "Failed to stop ETW session; hr=" << std::hex << hr;
    185 }
    186 
    187 }  // namespace logging_win
    188