summaryrefslogtreecommitdiffstats
path: root/chrome/test/logging/win/file_logger.cc
blob: b13af5cef57d11e6cc56d5f9b09cd20f02db0ebd (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
// Copyright (c) 2012 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "chrome/test/logging/win/file_logger.h"

#include <windows.h>
#include <guiddef.h>
#include <objbase.h>

#include <ios>

#include "base/files/file_path.h"
#include "base/logging.h"
#include "base/logging_win.h"
#include "base/strings/string16.h"
#include "base/strings/utf_string_conversions.h"
#include "base/trace_event/trace_event_win.h"
#include "base/win/event_trace_consumer.h"
#include "base/win/registry.h"

namespace logging_win {

namespace {

const wchar_t kChromeTestSession[] = L"chrome_tests";

// From chrome_tab.cc: {0562BFC3-2550-45b4-BD8E-A310583D3A6F}
const GUID kChromeFrameProvider =
    { 0x562bfc3, 0x2550, 0x45b4,
        { 0xbd, 0x8e, 0xa3, 0x10, 0x58, 0x3d, 0x3a, 0x6f } };

// From chrome/common/logging_chrome.cc: {7FE69228-633E-4f06-80C1-527FEA23E3A7}
const GUID kChromeTraceProviderName =
    { 0x7fe69228, 0x633e, 0x4f06,
        { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } };

// {81729947-CD2A-49e6-8885-785429F339F5}
const GUID kChromeTestsProvider =
    { 0x81729947, 0xcd2a, 0x49e6,
        { 0x88, 0x85, 0x78, 0x54, 0x29, 0xf3, 0x39, 0xf5 } };

// The configurations for the supported providers.  This must be in sync with
// FileLogger::EventProviderBits.
const struct {
  const GUID* provider_name;
  uint8 level;
  uint32 flags;
} kProviders[] = {
  { &kChromeTraceProviderName, 255, 0 },
  { &kChromeFrameProvider, 255, 0 },
  { &kChromeTestsProvider, 255, 0 },
  { &base::trace_event::kChromeTraceProviderName, 255, 0 }
};

static_assert((1 << arraysize(kProviders)) - 1 ==
                  FileLogger::kAllEventProviders,
              "size of kProviders is inconsistent with kAllEventProviders");

}  // namespace

bool FileLogger::is_initialized_ = false;

FileLogger::FileLogger()
    : event_provider_mask_() {
}

FileLogger::~FileLogger() {
  if (is_logging()) {
    LOG(ERROR)
      << __FUNCTION__ << " don't forget to call FileLogger::StopLogging()";
    StopLogging();
  }

  is_initialized_ = false;
}

// Returns false if all providers could not be enabled.  A log message is
// produced for each provider that could not be enabled.
bool FileLogger::EnableProviders() {
  // Default to false if there's at least one provider.
  bool result = (event_provider_mask_ == 0);

  // Generate ETW log events for this test binary.  Log messages at and above
  // logging::GetMinLogLevel() will continue to go to stderr as well.  This
  // leads to double logging in case of test failures: each LOG statement at
  // or above the min level will go to stderr during test execution, and then
  // all events logged to the file session will be dumped again.  If this
  // turns out to be an issue, one could call logging::SetMinLogLevel(INT_MAX)
  // here (stashing away the previous min log level to be restored in
  // DisableProviders) to suppress stderr logging during test execution.  Then
  // those events in the file that were logged at/above the old min level from
  // the test binary could be dumped to stderr if there were no failures.
  if (event_provider_mask_ & CHROME_TESTS_LOG_PROVIDER)
    logging::LogEventProvider::Initialize(kChromeTestsProvider);

  HRESULT hr = S_OK;
  for (size_t i = 0; i < arraysize(kProviders); ++i) {
    if (event_provider_mask_ & (1 << i)) {
      hr = controller_.EnableProvider(*kProviders[i].provider_name,
                                      kProviders[i].level,
                                      kProviders[i].flags);
      if (FAILED(hr)) {
        LOG(ERROR) << "Failed to enable event provider " << i
                   << "; hr=" << std::hex << hr;
      } else {
        result = true;
      }
    }
  }

  return result;
}

void FileLogger::DisableProviders() {
  HRESULT hr = S_OK;
  for (size_t i = 0; i < arraysize(kProviders); ++i) {
    if (event_provider_mask_ & (1 << i)) {
      hr = controller_.DisableProvider(*kProviders[i].provider_name);
      LOG_IF(ERROR, FAILED(hr)) << "Failed to disable event provider "
                                << i << "; hr=" << std::hex << hr;
    }
  }

  if (event_provider_mask_ & CHROME_TESTS_LOG_PROVIDER)
    logging::LogEventProvider::Uninitialize();
}

void FileLogger::Initialize() {
  Initialize(kAllEventProviders);
}

void FileLogger::Initialize(uint32 event_provider_mask) {
  CHECK(!is_initialized_);

  // Stop a previous session that wasn't shut down properly.
  base::win::EtwTraceProperties ignore;
  HRESULT hr = base::win::EtwTraceController::Stop(kChromeTestSession,
                                                   &ignore);
  LOG_IF(ERROR, FAILED(hr) &&
             hr != HRESULT_FROM_WIN32(ERROR_WMI_INSTANCE_NOT_FOUND))
      << "Failed to stop a previous trace session; hr=" << std::hex << hr;

  event_provider_mask_ = event_provider_mask;

  is_initialized_ = true;
}

bool FileLogger::StartLogging(const base::FilePath& log_file) {
  HRESULT hr =
      controller_.StartFileSession(kChromeTestSession,
                                   log_file.value().c_str(), false);
  if (SUCCEEDED(hr)) {
    // Ignore the return value here in the hopes that at least one provider was
    // enabled.
    if (!EnableProviders()) {
      LOG(ERROR) << "Failed to enable any provider.";
      controller_.Stop(NULL);
      return false;
    }
  } else {
    if (hr == HRESULT_FROM_WIN32(ERROR_ACCESS_DENIED)) {
      LOG(WARNING) << "Access denied while trying to start trace session. "
                      "This is expected when not running as an administrator.";
    } else {
      LOG(ERROR) << "Failed to start trace session to file " << log_file.value()
                 << "; hr=" << std::hex << hr;
    }
    return false;
  }
  return true;
}

void FileLogger::StopLogging() {
  HRESULT hr = S_OK;

  DisableProviders();

  hr = controller_.Flush(NULL);
  LOG_IF(ERROR, FAILED(hr))
      << "Failed to flush events; hr=" << std::hex << hr;
  hr = controller_.Stop(NULL);
  LOG_IF(ERROR, FAILED(hr))
      << "Failed to stop ETW session; hr=" << std::hex << hr;
}

}  // namespace logging_win