1// Copyright (c) 2011 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 "base/debug/trace_event.h"
6
7#include <strstream>
8
9#include "base/at_exit.h"
10#include "base/basictypes.h"
11#include "base/debug/trace_event.h"
12#include "base/debug/trace_event_win.h"
13#include "base/files/file_util.h"
14#include "base/win/event_trace_consumer.h"
15#include "base/win/event_trace_controller.h"
16#include "base/win/event_trace_provider.h"
17#include "base/win/windows_version.h"
18#include "testing/gmock/include/gmock/gmock.h"
19#include "testing/gtest/include/gtest/gtest.h"
20#include <initguid.h>  // NOLINT - must be last include.
21
22namespace base {
23namespace debug {
24
25namespace {
26
27using testing::_;
28using testing::AnyNumber;
29using testing::InSequence;
30using testing::Ge;
31using testing::Le;
32using testing::NotNull;
33
34using base::win::EtwEventType;
35using base::win::EtwTraceConsumerBase;
36using base::win::EtwTraceController;
37using base::win::EtwTraceProperties;
38
39// Data for unittests traces.
40const char kEmpty[] = "";
41const char kName[] = "unittest.trace_name";
42const char kExtra[] = "UnittestDummyExtraString";
43const void* kId = kName;
44
45const wchar_t kTestSessionName[] = L"TraceEvent unittest session";
46
47MATCHER_P(BufferStartsWith, str, "Buffer starts with") {
48  return memcmp(arg, str.c_str(), str.length()) == 0;
49}
50
51// Duplicated from <evntrace.h> to fix link problems.
52DEFINE_GUID( /* 68fdd900-4a3e-11d1-84f4-0000f80464e3 */
53    kEventTraceGuid,
54    0x68fdd900,
55    0x4a3e,
56    0x11d1,
57    0x84, 0xf4, 0x00, 0x00, 0xf8, 0x04, 0x64, 0xe3);
58
59class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> {
60 public:
61  TestEventConsumer() {
62    EXPECT_TRUE(current_ == NULL);
63    current_ = this;
64  }
65
66  ~TestEventConsumer() {
67    EXPECT_TRUE(current_ == this);
68    current_ = NULL;
69  }
70
71  MOCK_METHOD4(Event, void(REFGUID event_class,
72                      EtwEventType event_type,
73                      size_t buf_len,
74                      const void* buf));
75
76  static void ProcessEvent(EVENT_TRACE* event) {
77    ASSERT_TRUE(current_ != NULL);
78    current_->Event(event->Header.Guid,
79                    event->Header.Class.Type,
80                    event->MofLength,
81                    event->MofData);
82  }
83
84 private:
85  static TestEventConsumer* current_;
86};
87
88TestEventConsumer* TestEventConsumer::current_ = NULL;
89
90class TraceEventWinTest: public testing::Test {
91 public:
92  TraceEventWinTest() {
93  }
94
95  void SetUp() {
96    bool is_xp = win::GetVersion() < base::win::VERSION_VISTA;
97
98    if (is_xp) {
99      // Tear down any dangling session from an earlier failing test.
100      EtwTraceProperties ignore;
101      EtwTraceController::Stop(kTestSessionName, &ignore);
102    }
103
104    // Resurrect and initialize the TraceLog singleton instance.
105    // On Vista and better, we need the provider registered before we
106    // start the private, in-proc session, but on XP we need the global
107    // session created and the provider enabled before we register our
108    // provider.
109    TraceEventETWProvider* tracelog = NULL;
110    if (!is_xp) {
111      TraceEventETWProvider::Resurrect();
112      tracelog = TraceEventETWProvider::GetInstance();
113      ASSERT_TRUE(tracelog != NULL);
114      ASSERT_FALSE(tracelog->IsTracing());
115    }
116
117    // Create the log file.
118    ASSERT_TRUE(base::CreateTemporaryFile(&log_file_));
119
120    // Create a private log session on the file.
121    EtwTraceProperties prop;
122    ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerFileName(log_file_.value().c_str()));
123    EVENT_TRACE_PROPERTIES& p = *prop.get();
124    p.Wnode.ClientContext = 1;  // QPC timer accuracy.
125    p.LogFileMode = EVENT_TRACE_FILE_MODE_SEQUENTIAL;   // Sequential log.
126
127    // On Vista and later, we create a private in-process log session, because
128    // otherwise we'd need administrator privileges. Unfortunately we can't
129    // do the same on XP and better, because the semantics of a private
130    // logger session are different, and the IN_PROC flag is not supported.
131    if (!is_xp) {
132      p.LogFileMode |= EVENT_TRACE_PRIVATE_IN_PROC |  // In-proc for non-admin.
133          EVENT_TRACE_PRIVATE_LOGGER_MODE;  // Process-private log.
134    }
135
136    p.MaximumFileSize = 100;  // 100M file size.
137    p.FlushTimer = 1;  // 1 second flush lag.
138    ASSERT_HRESULT_SUCCEEDED(controller_.Start(kTestSessionName, &prop));
139
140    // Enable the TraceLog provider GUID.
141    ASSERT_HRESULT_SUCCEEDED(
142        controller_.EnableProvider(kChromeTraceProviderName,
143                                   TRACE_LEVEL_INFORMATION,
144                                   0));
145
146    if (is_xp) {
147      TraceEventETWProvider::Resurrect();
148      tracelog = TraceEventETWProvider::GetInstance();
149    }
150    ASSERT_TRUE(tracelog != NULL);
151    EXPECT_TRUE(tracelog->IsTracing());
152  }
153
154  void TearDown() {
155    EtwTraceProperties prop;
156    if (controller_.session() != 0)
157      EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
158
159    if (!log_file_.value().empty())
160      base::DeleteFile(log_file_, false);
161
162    // We want our singleton torn down after each test.
163    TraceLog::DeleteForTesting();
164  }
165
166  void ExpectEvent(REFGUID guid,
167                   EtwEventType type,
168                   const char* name,
169                   size_t name_len,
170                   const void* id,
171                   const char* extra,
172                   size_t extra_len) {
173    // Build the trace event buffer we expect will result from this.
174    std::stringbuf str;
175    str.sputn(name, name_len + 1);
176    str.sputn(reinterpret_cast<const char*>(&id), sizeof(id));
177    str.sputn(extra, extra_len + 1);
178
179    // And set up the expectation for the event callback.
180    EXPECT_CALL(consumer_, Event(guid,
181                                 type,
182                                 testing::Ge(str.str().length()),
183                                 BufferStartsWith(str.str())));
184  }
185
186  void ExpectPlayLog() {
187    // Ignore EventTraceGuid events.
188    EXPECT_CALL(consumer_, Event(kEventTraceGuid, _, _, _))
189        .Times(AnyNumber());
190  }
191
192  void PlayLog() {
193    EtwTraceProperties prop;
194    EXPECT_HRESULT_SUCCEEDED(controller_.Flush(&prop));
195    EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
196    ASSERT_HRESULT_SUCCEEDED(
197        consumer_.OpenFileSession(log_file_.value().c_str()));
198
199    ASSERT_HRESULT_SUCCEEDED(consumer_.Consume());
200  }
201
202 private:
203  // We want our singleton torn down after each test.
204  ShadowingAtExitManager at_exit_manager_;
205  EtwTraceController controller_;
206  FilePath log_file_;
207  TestEventConsumer consumer_;
208};
209
210}  // namespace
211
212
213TEST_F(TraceEventWinTest, TraceLog) {
214  ExpectPlayLog();
215
216  // The events should arrive in the same sequence as the expects.
217  InSequence in_sequence;
218
219  // Full argument version, passing lengths explicitly.
220  TraceEventETWProvider::Trace(kName,
221                        strlen(kName),
222                        TRACE_EVENT_PHASE_BEGIN,
223                        kId,
224                        kExtra,
225                        strlen(kExtra));
226
227  ExpectEvent(kTraceEventClass32,
228              kTraceEventTypeBegin,
229              kName, strlen(kName),
230              kId,
231              kExtra, strlen(kExtra));
232
233  // Const char* version.
234  TraceEventETWProvider::Trace(static_cast<const char*>(kName),
235                        TRACE_EVENT_PHASE_END,
236                        kId,
237                        static_cast<const char*>(kExtra));
238
239  ExpectEvent(kTraceEventClass32,
240              kTraceEventTypeEnd,
241              kName, strlen(kName),
242              kId,
243              kExtra, strlen(kExtra));
244
245  // std::string extra version.
246  TraceEventETWProvider::Trace(static_cast<const char*>(kName),
247                        TRACE_EVENT_PHASE_INSTANT,
248                        kId,
249                        std::string(kExtra));
250
251  ExpectEvent(kTraceEventClass32,
252              kTraceEventTypeInstant,
253              kName, strlen(kName),
254              kId,
255              kExtra, strlen(kExtra));
256
257
258  // Test for sanity on NULL inputs.
259  TraceEventETWProvider::Trace(NULL,
260                        0,
261                        TRACE_EVENT_PHASE_BEGIN,
262                        kId,
263                        NULL,
264                        0);
265
266  ExpectEvent(kTraceEventClass32,
267              kTraceEventTypeBegin,
268              kEmpty, 0,
269              kId,
270              kEmpty, 0);
271
272  TraceEventETWProvider::Trace(NULL,
273                        TraceEventETWProvider::kUseStrlen,
274                        TRACE_EVENT_PHASE_END,
275                        kId,
276                        NULL,
277                        TraceEventETWProvider::kUseStrlen);
278
279  ExpectEvent(kTraceEventClass32,
280              kTraceEventTypeEnd,
281              kEmpty, 0,
282              kId,
283              kEmpty, 0);
284
285  PlayLog();
286}
287
288TEST_F(TraceEventWinTest, Macros) {
289  ExpectPlayLog();
290
291  // The events should arrive in the same sequence as the expects.
292  InSequence in_sequence;
293
294  TRACE_EVENT_BEGIN_ETW(kName, kId, kExtra);
295  ExpectEvent(kTraceEventClass32,
296              kTraceEventTypeBegin,
297              kName, strlen(kName),
298              kId,
299              kExtra, strlen(kExtra));
300
301  TRACE_EVENT_END_ETW(kName, kId, kExtra);
302  ExpectEvent(kTraceEventClass32,
303              kTraceEventTypeEnd,
304              kName, strlen(kName),
305              kId,
306              kExtra, strlen(kExtra));
307
308  TRACE_EVENT_INSTANT_ETW(kName, kId, kExtra);
309  ExpectEvent(kTraceEventClass32,
310              kTraceEventTypeInstant,
311              kName, strlen(kName),
312              kId,
313              kExtra, strlen(kExtra));
314
315  PlayLog();
316}
317
318}  // namespace debug
319}  // namespace base
320