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