1 // Copyright 2019 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 "util/trace_logging.h"
6
7 #include <chrono>
8 #include <thread>
9
10 #include "absl/types/optional.h"
11 #include "gmock/gmock.h"
12 #include "gtest/gtest.h"
13 #include "platform/test/trace_logging_helpers.h"
14
15 namespace openscreen {
16 namespace {
17
18 #if defined(ENABLE_TRACE_LOGGING)
19 constexpr TraceHierarchyParts kAllParts = static_cast<TraceHierarchyParts>(
20 TraceHierarchyParts::kRoot | TraceHierarchyParts::kParent |
21 TraceHierarchyParts::kCurrent);
22 constexpr TraceHierarchyParts kParentAndRoot = static_cast<TraceHierarchyParts>(
23 TraceHierarchyParts::kRoot | TraceHierarchyParts::kParent);
24 constexpr TraceId kEmptyId = TraceId{0};
25 #endif
26
27 using ::testing::_;
28 using ::testing::AtLeast;
29 using ::testing::DoAll;
30 using ::testing::Invoke;
31
32 // All the unit tests below should use TestTraceLoggingPlatform for the
33 // library's tracing output mock. This is a StrictMock to ensure that, when not
34 // compiling with ENABLE_TRACE_LOGGING, the mock receives no method calls.
35 using StrictMockLoggingPlatform = ::testing::StrictMock<MockLoggingPlatform>;
36
TEST(TraceLoggingTest,MacroCallScopedDoesNotSegFault)37 TEST(TraceLoggingTest, MacroCallScopedDoesNotSegFault) {
38 StrictMockLoggingPlatform platform;
39 #if defined(ENABLE_TRACE_LOGGING)
40 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
41 .Times(AtLeast(1));
42 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _)).Times(1);
43 #endif
44 { TRACE_SCOPED(TraceCategory::Value::kAny, "test"); }
45 }
46
TEST(TraceLoggingTest,MacroCallDefaultScopedDoesNotSegFault)47 TEST(TraceLoggingTest, MacroCallDefaultScopedDoesNotSegFault) {
48 StrictMockLoggingPlatform platform;
49 #if defined(ENABLE_TRACE_LOGGING)
50 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
51 .Times(AtLeast(1));
52 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _)).Times(1);
53 #endif
54 { TRACE_DEFAULT_SCOPED(TraceCategory::Value::kAny); }
55 }
56
TEST(TraceLoggingTest,MacroCallUnscopedDoesNotSegFault)57 TEST(TraceLoggingTest, MacroCallUnscopedDoesNotSegFault) {
58 StrictMockLoggingPlatform platform;
59 #if defined(ENABLE_TRACE_LOGGING)
60 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
61 .Times(AtLeast(1));
62 EXPECT_CALL(platform, LogAsyncStart(_, _, _, _, _)).Times(1);
63 #endif
64 { TRACE_ASYNC_START(TraceCategory::Value::kAny, "test"); }
65 }
66
TEST(TraceLoggingTest,MacroVariablesUniquelyNames)67 TEST(TraceLoggingTest, MacroVariablesUniquelyNames) {
68 StrictMockLoggingPlatform platform;
69 #if defined(ENABLE_TRACE_LOGGING)
70 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
71 .Times(AtLeast(1));
72 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _)).Times(3);
73 EXPECT_CALL(platform, LogAsyncStart(_, _, _, _, _)).Times(2);
74 #endif
75
76 {
77 TRACE_SCOPED(TraceCategory::Value::kAny, "test1");
78 TRACE_SCOPED(TraceCategory::Value::kAny, "test2");
79 TRACE_ASYNC_START(TraceCategory::Value::kAny, "test3");
80 TRACE_ASYNC_START(TraceCategory::Value::kAny, "test4");
81 TRACE_DEFAULT_SCOPED(TraceCategory::Value::kAny);
82 }
83 }
84
TEST(TraceLoggingTest,ExpectTimestampsReflectDelay)85 TEST(TraceLoggingTest, ExpectTimestampsReflectDelay) {
86 constexpr uint32_t delay_in_ms = 50;
87 StrictMockLoggingPlatform platform;
88 #if defined(ENABLE_TRACE_LOGGING)
89 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
90 .Times(AtLeast(1));
91 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
92 .WillOnce(DoAll(Invoke(ValidateTraceTimestampDiff<delay_in_ms>),
93 Invoke(ValidateTraceErrorCode<Error::Code::kNone>)));
94 #endif
95
96 {
97 TRACE_SCOPED(TraceCategory::Value::kAny, "Name");
98 std::this_thread::sleep_for(std::chrono::milliseconds(delay_in_ms));
99 }
100 }
101
TEST(TraceLoggingTest,ExpectErrorsPassedToResult)102 TEST(TraceLoggingTest, ExpectErrorsPassedToResult) {
103 constexpr Error::Code result_code = Error::Code::kParseError;
104 StrictMockLoggingPlatform platform;
105 #if defined(ENABLE_TRACE_LOGGING)
106 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
107 .Times(AtLeast(1));
108 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
109 .WillOnce(Invoke(ValidateTraceErrorCode<result_code>));
110 #endif
111
112 {
113 TRACE_SCOPED(TraceCategory::Value::kAny, "Name");
114 TRACE_SET_RESULT(result_code);
115 }
116 }
117
TEST(TraceLoggingTest,ExpectUnsetTraceIdNotSet)118 TEST(TraceLoggingTest, ExpectUnsetTraceIdNotSet) {
119 StrictMockLoggingPlatform platform;
120 #if defined(ENABLE_TRACE_LOGGING)
121 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
122 .Times(AtLeast(1));
123 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _)).Times(1);
124 #endif
125
126 TraceIdHierarchy h = {kUnsetTraceId, kUnsetTraceId, kUnsetTraceId};
127 {
128 TRACE_SCOPED(TraceCategory::Value::kAny, "Name", h);
129
130 auto ids = TRACE_HIERARCHY;
131 EXPECT_NE(ids.current, kUnsetTraceId);
132 EXPECT_NE(ids.parent, kUnsetTraceId);
133 EXPECT_NE(ids.root, kUnsetTraceId);
134 }
135 }
136
TEST(TraceLoggingTest,ExpectCreationWithIdsToWork)137 TEST(TraceLoggingTest, ExpectCreationWithIdsToWork) {
138 constexpr TraceId current = 0x32;
139 constexpr TraceId parent = 0x47;
140 constexpr TraceId root = 0x84;
141 StrictMockLoggingPlatform platform;
142 #if defined(ENABLE_TRACE_LOGGING)
143 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
144 .Times(AtLeast(1));
145 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
146 .WillOnce(
147 DoAll(Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
148 Invoke(ValidateTraceIdHierarchyOnSyncTrace<current, parent,
149 root, kAllParts>)));
150 #endif
151
152 {
153 TraceIdHierarchy h = {current, parent, root};
154 TRACE_SCOPED(TraceCategory::Value::kAny, "Name", h);
155
156 #if defined(ENABLE_TRACE_LOGGING)
157 auto ids = TRACE_HIERARCHY;
158 EXPECT_EQ(ids.current, current);
159 EXPECT_EQ(ids.parent, parent);
160 EXPECT_EQ(ids.root, root);
161
162 EXPECT_EQ(TRACE_CURRENT_ID, current);
163 EXPECT_EQ(TRACE_ROOT_ID, root);
164 #endif
165 }
166 }
167
TEST(TraceLoggingTest,ExpectHirearchyToBeApplied)168 TEST(TraceLoggingTest, ExpectHirearchyToBeApplied) {
169 constexpr TraceId current = 0x32;
170 constexpr TraceId parent = 0x47;
171 constexpr TraceId root = 0x84;
172 StrictMockLoggingPlatform platform;
173 #if defined(ENABLE_TRACE_LOGGING)
174 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
175 .Times(AtLeast(1));
176 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
177 .WillOnce(DoAll(
178 Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
179 Invoke(ValidateTraceIdHierarchyOnSyncTrace<kEmptyId, current, root,
180 kParentAndRoot>)))
181 .WillOnce(
182 DoAll(Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
183 Invoke(ValidateTraceIdHierarchyOnSyncTrace<current, parent,
184 root, kAllParts>)));
185 #endif
186
187 {
188 TraceIdHierarchy h = {current, parent, root};
189 TRACE_SCOPED(TraceCategory::Value::kAny, "Name", h);
190 #if defined(ENABLE_TRACE_LOGGING)
191 auto ids = TRACE_HIERARCHY;
192 EXPECT_EQ(ids.current, current);
193 EXPECT_EQ(ids.parent, parent);
194 EXPECT_EQ(ids.root, root);
195 #endif
196
197 TRACE_SCOPED(TraceCategory::Value::kAny, "Name");
198 #if defined(ENABLE_TRACE_LOGGING)
199 ids = TRACE_HIERARCHY;
200 EXPECT_NE(ids.current, current);
201 EXPECT_EQ(ids.parent, current);
202 EXPECT_EQ(ids.root, root);
203 #endif
204 }
205 }
206
TEST(TraceLoggingTest,ExpectHirearchyToEndAfterScopeWhenSetWithSetter)207 TEST(TraceLoggingTest, ExpectHirearchyToEndAfterScopeWhenSetWithSetter) {
208 constexpr TraceId current = 0x32;
209 constexpr TraceId parent = 0x47;
210 constexpr TraceId root = 0x84;
211 StrictMockLoggingPlatform platform;
212 #if defined(ENABLE_TRACE_LOGGING)
213 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
214 .Times(AtLeast(1));
215 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
216 .WillOnce(DoAll(
217 Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
218 Invoke(ValidateTraceIdHierarchyOnSyncTrace<kEmptyId, current, root,
219 kParentAndRoot>)));
220 #endif
221
222 {
223 TraceIdHierarchy ids = {current, parent, root};
224 TRACE_SET_HIERARCHY(ids);
225 {
226 TRACE_SCOPED(TraceCategory::Value::kAny, "Name");
227 ids = TRACE_HIERARCHY;
228 #if defined(ENABLE_TRACE_LOGGING)
229 EXPECT_NE(ids.current, current);
230 EXPECT_EQ(ids.parent, current);
231 EXPECT_EQ(ids.root, root);
232 #endif
233 }
234
235 ids = TRACE_HIERARCHY;
236 #if defined(ENABLE_TRACE_LOGGING)
237 EXPECT_EQ(ids.current, current);
238 EXPECT_EQ(ids.parent, parent);
239 EXPECT_EQ(ids.root, root);
240 #endif
241 }
242 }
243
TEST(TraceLoggingTest,ExpectHierarchyToEndAfterScope)244 TEST(TraceLoggingTest, ExpectHierarchyToEndAfterScope) {
245 constexpr TraceId current = 0x32;
246 constexpr TraceId parent = 0x47;
247 constexpr TraceId root = 0x84;
248 StrictMockLoggingPlatform platform;
249 #if defined(ENABLE_TRACE_LOGGING)
250 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
251 .Times(AtLeast(1));
252 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
253 .WillOnce(DoAll(
254 Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
255 Invoke(ValidateTraceIdHierarchyOnSyncTrace<kEmptyId, current, root,
256 kParentAndRoot>)))
257 .WillOnce(
258 DoAll(Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
259 Invoke(ValidateTraceIdHierarchyOnSyncTrace<current, parent,
260 root, kAllParts>)));
261 #endif
262
263 {
264 TraceIdHierarchy ids = {current, parent, root};
265 TRACE_SCOPED(TraceCategory::Value::kAny, "Name", ids);
266 {
267 TRACE_SCOPED(TraceCategory::Value::kAny, "Name");
268 ids = TRACE_HIERARCHY;
269 #if defined(ENABLE_TRACE_LOGGING)
270 EXPECT_NE(ids.current, current);
271 EXPECT_EQ(ids.parent, current);
272 EXPECT_EQ(ids.root, root);
273 #endif
274 }
275
276 ids = TRACE_HIERARCHY;
277 #if defined(ENABLE_TRACE_LOGGING)
278 EXPECT_EQ(ids.current, current);
279 EXPECT_EQ(ids.parent, parent);
280 EXPECT_EQ(ids.root, root);
281 #endif
282 }
283 }
284
TEST(TraceLoggingTest,ExpectSetHierarchyToApply)285 TEST(TraceLoggingTest, ExpectSetHierarchyToApply) {
286 constexpr TraceId current = 0x32;
287 constexpr TraceId parent = 0x47;
288 constexpr TraceId root = 0x84;
289 StrictMockLoggingPlatform platform;
290 #if defined(ENABLE_TRACE_LOGGING)
291 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
292 .Times(AtLeast(1));
293 EXPECT_CALL(platform, LogTrace(_, _, _, _, _, _, _))
294 .WillOnce(DoAll(
295 Invoke(ValidateTraceErrorCode<Error::Code::kNone>),
296 Invoke(ValidateTraceIdHierarchyOnSyncTrace<kEmptyId, current, root,
297 kParentAndRoot>)));
298 #endif
299
300 {
301 TraceIdHierarchy ids = {current, parent, root};
302 TRACE_SET_HIERARCHY(ids);
303 ids = TRACE_HIERARCHY;
304 #if defined(ENABLE_TRACE_LOGGING)
305 EXPECT_EQ(ids.current, current);
306 EXPECT_EQ(ids.parent, parent);
307 EXPECT_EQ(ids.root, root);
308 #endif
309
310 TRACE_SCOPED(TraceCategory::Value::kAny, "Name");
311 ids = TRACE_HIERARCHY;
312 #if defined(ENABLE_TRACE_LOGGING)
313 EXPECT_NE(ids.current, current);
314 EXPECT_EQ(ids.parent, current);
315 EXPECT_EQ(ids.root, root);
316 #endif
317 }
318 }
319
TEST(TraceLoggingTest,CheckTraceAsyncStartLogsCorrectly)320 TEST(TraceLoggingTest, CheckTraceAsyncStartLogsCorrectly) {
321 StrictMockLoggingPlatform platform;
322 #if defined(ENABLE_TRACE_LOGGING)
323 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
324 .Times(AtLeast(1));
325 EXPECT_CALL(platform, LogAsyncStart(_, _, _, _, _)).Times(1);
326 #endif
327
328 { TRACE_ASYNC_START(TraceCategory::Value::kAny, "Name"); }
329 }
330
TEST(TraceLoggingTest,CheckTraceAsyncStartSetsHierarchy)331 TEST(TraceLoggingTest, CheckTraceAsyncStartSetsHierarchy) {
332 constexpr TraceId current = 32;
333 constexpr TraceId parent = 47;
334 constexpr TraceId root = 84;
335 StrictMockLoggingPlatform platform;
336 #if defined(ENABLE_TRACE_LOGGING)
337 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
338 .Times(AtLeast(1));
339 EXPECT_CALL(platform, LogAsyncStart(_, _, _, _, _))
340 .WillOnce(
341 Invoke(ValidateTraceIdHierarchyOnAsyncTrace<kEmptyId, current, root,
342 kParentAndRoot>));
343 #endif
344
345 {
346 TraceIdHierarchy ids = {current, parent, root};
347 TRACE_SET_HIERARCHY(ids);
348 {
349 TRACE_ASYNC_START(TraceCategory::Value::kAny, "Name");
350 ids = TRACE_HIERARCHY;
351 #if defined(ENABLE_TRACE_LOGGING)
352 EXPECT_NE(ids.current, current);
353 EXPECT_EQ(ids.parent, current);
354 EXPECT_EQ(ids.root, root);
355 #endif
356 }
357
358 ids = TRACE_HIERARCHY;
359 #if defined(ENABLE_TRACE_LOGGING)
360 EXPECT_EQ(ids.current, current);
361 EXPECT_EQ(ids.parent, parent);
362 EXPECT_EQ(ids.root, root);
363 #endif
364 }
365 }
366
TEST(TraceLoggingTest,CheckTraceAsyncEndLogsCorrectly)367 TEST(TraceLoggingTest, CheckTraceAsyncEndLogsCorrectly) {
368 constexpr TraceId id = 12345;
369 constexpr Error::Code result = Error::Code::kAgain;
370 StrictMockLoggingPlatform platform;
371 #if defined(ENABLE_TRACE_LOGGING)
372 EXPECT_CALL(platform, IsTraceLoggingEnabled(TraceCategory::Value::kAny))
373 .Times(AtLeast(1));
374 EXPECT_CALL(platform, LogAsyncEnd(_, _, _, id, result)).Times(1);
375 #endif
376
377 TRACE_ASYNC_END(TraceCategory::Value::kAny, id, result);
378 }
379
380 } // namespace
381 } // namespace openscreen
382