src/chrome/test/logging/win/file_logger.cc

   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