1/* -*- Mode: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2/*
3 *     Copyright 2016 Couchbase, Inc
4 *
5 *   Licensed under the Apache License, Version 2.0 (the "License");
6 *   you may not use this file except in compliance with the License.
7 *   You may obtain a copy of the License at
8 *
9 *       http://www.apache.org/licenses/LICENSE-2.0
10 *
11 *   Unless required by applicable law or agreed to in writing, software
12 *   distributed under the License is distributed on an "AS IS" BASIS,
13 *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 *   See the License for the specific language governing permissions and
15 *   limitations under the License.
16 */
17
18#include <thread>
19#include <vector>
20
21#include <gmock/gmock.h>
22#include <gtest/gtest.h>
23
24#include "phosphor/trace_buffer.h"
25#include "phosphor/trace_log.h"
26#include "utils/memory.h"
27
28#include "mock_buffer.h"
29#include "mock_stats_callback.h"
30
31using namespace phosphor;
32
33#ifdef _WIN32
34int setenv(const char* name, const char* value, int overwrite);
35#endif
36
37/*
38 * Basic tracepoint_infos used in tests
39 */
40phosphor::tracepoint_info tpi0 = {
41        "category",
42        "name",
43        TraceEvent::Type::Instant,
44        {{"arg1", "arg2"}},
45        {{TraceArgument::Type::is_none, TraceArgument::Type::is_none}}
46};
47phosphor::tracepoint_info tpi1 = {
48        "category",
49        "name",
50        TraceEvent::Type::Instant,
51        {{"arg1", "arg2"}},
52        {{TraceArgument::Type::is_int, TraceArgument::Type::is_none}}
53};
54phosphor::tracepoint_info tpi2 = {
55        "category",
56        "name",
57        TraceEvent::Type::Instant,
58        {{"arg1", "arg2"}},
59        {{TraceArgument::Type::is_int, TraceArgument::Type::is_int}}
60};
61
62class MockTraceLog : public TraceLog {
63    friend class TraceLogTest;
64    using TraceLog::TraceLog;
65};
66
67class TraceLogTest : public testing::Test {
68public:
69    static const int min_buffer_size = sizeof(TraceChunk);
70
71    TraceLogTest() {
72        trace_log.registerThread();
73    }
74    virtual ~TraceLogTest() {
75        trace_log.deregisterThread();
76    }
77
78    void start_basic() {
79        trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size));
80    }
81
82    void log_event() {
83        trace_log.logEvent(&tpi2, 0, 0);
84    }
85
86    void log_event_all_types() {
87        trace_log.logEvent(&tpi0, 0, 0);
88        trace_log.logEvent(&tpi1, 0, 0);
89        trace_log.logEvent(&tpi2, 0, 0);
90    }
91
92protected:
93    MockTraceLog trace_log;
94};
95
96TEST_F(TraceLogTest, smallBufferThrow) {
97    EXPECT_THROW(trace_log.start(TraceConfig(BufferMode::fixed, 0)),
98                 std::invalid_argument);
99
100    trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size));
101}
102
103TEST_F(TraceLogTest, isEnabled) {
104    EXPECT_FALSE(trace_log.isEnabled());
105    start_basic();
106    EXPECT_TRUE(trace_log.isEnabled());
107    trace_log.stop();
108    EXPECT_FALSE(trace_log.isEnabled());
109}
110
111TEST_F(TraceLogTest, multiStart) {
112    TraceConfig configA(BufferMode::ring, min_buffer_size);
113    TraceConfig configB(BufferMode::fixed, min_buffer_size * 2);
114
115    trace_log.start(configA);
116    EXPECT_TRUE(trace_log.isEnabled());
117    EXPECT_EQ(*configA.toString(), *trace_log.getTraceConfig().toString());
118
119    trace_log.start(configB);
120    EXPECT_TRUE(trace_log.isEnabled());
121    EXPECT_EQ(*configB.toString(), *trace_log.getTraceConfig().toString());
122    trace_log.stop();
123    EXPECT_FALSE(trace_log.isEnabled());
124    trace_log.stop();
125    EXPECT_FALSE(trace_log.isEnabled());
126}
127
128TEST_F(TraceLogTest, EnabledBufferGetThrow) {
129    EXPECT_EQ(nullptr, trace_log.getBuffer());
130    start_basic();
131    EXPECT_THROW(trace_log.getBuffer(), std::logic_error);
132    trace_log.stop();
133    EXPECT_NE(nullptr, trace_log.getBuffer());
134}
135
136TEST_F(TraceLogTest, EnabledContextGetThrow) {
137    EXPECT_NO_THROW(trace_log.getTraceContext());
138    start_basic();
139    EXPECT_THROW(trace_log.getTraceContext(), std::logic_error);
140    trace_log.stop();
141    EXPECT_NO_THROW(trace_log.getTraceContext());
142}
143
144TEST_F(TraceLogTest, bufferGenerationCheck) {
145    start_basic();
146    trace_log.stop();
147    TraceContext context = trace_log.getTraceContext();
148    EXPECT_EQ(0, context.getBuffer()->getGeneration());
149    start_basic();
150    trace_log.stop();
151    context = trace_log.getTraceContext();
152    EXPECT_EQ(1, context.getBuffer()->getGeneration());
153}
154
155TEST_F(TraceLogTest, logTillFullAndEvenThen) {
156    trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size * 4));
157
158    while (trace_log.isEnabled()) {
159        log_event_all_types();
160    }
161    log_event_all_types();
162}
163
164TEST_F(TraceLogTest, logTillFullAndEvenThenButReload) {
165    trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size * 4));
166
167    while (trace_log.isEnabled()) {
168        log_event();
169    }
170    trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size * 4));
171
172    while (trace_log.isEnabled()) {
173        log_event();
174    }
175}
176
177TEST_F(TraceLogTest, logTillFullThreaded) {
178    const int thread_count = 8;
179    std::vector<std::thread> threads;
180    trace_log.start(
181        TraceConfig(BufferMode::fixed, min_buffer_size * thread_count * 4));
182
183    for (int i = 0; i < thread_count; ++i) {
184        threads.emplace_back([this]() {
185            while (trace_log.isEnabled()) {
186                log_event();
187            }
188        });
189    }
190    for (std::thread& thread : threads) {
191        thread.join();
192    };
193}
194
195TEST_F(TraceLogTest, StopRestartVerify) {
196    // Start tracing and ensure we've taken a chunk from it
197    start_basic();
198    trace_log.logEvent(&tpi0, 0, 0);
199
200    // Stop tracing (and invalidate the chunk we're currently holding)
201    trace_log.stop();
202
203    // Restart tracing and attempt to log an event
204    start_basic();
205
206    static tracepoint_info tpi0_alt = {
207        "category2",
208        "name",
209        TraceEvent::Type::Instant,
210        {{"arg1", "arg2"}},
211        {{TraceArgument::Type::is_none, TraceArgument::Type::is_none}}
212    };
213    trace_log.logEvent(&tpi0_alt, 0, 0);
214
215    // Fetch the buffer and ensure that it contains our second event
216    // (i.e. we didn't lose the event in the
217    // process of resetting the ChunkTenant)
218    trace_log.stop();
219    auto context = trace_log.getTraceContext();
220    auto event = context.getBuffer()->begin();
221    ASSERT_NE(context.getBuffer()->end(), event);
222    EXPECT_STREQ("category2", (*event).getCategory());
223}
224
225TEST_F(TraceLogTest, CategoryConfig) {
226    trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size)
227                        .setCategories({{"*"}}, {{"world"}}));
228    EXPECT_EQ(CategoryStatus::Enabled, trace_log.getCategoryStatus("hello"));
229    EXPECT_EQ(CategoryStatus::Disabled, trace_log.getCategoryStatus("world"));
230}
231
232TEST_F(TraceLogTest, GetConfig) {
233    TraceConfig config(BufferMode::fixed, min_buffer_size);
234    config.setCategories({{"*"}}, {{"world"}});
235
236    trace_log.start(config);
237    EXPECT_EQ(*config.toString(), *trace_log.getTraceConfig().toString());
238    EXPECT_EQ(BufferMode::fixed, trace_log.getTraceConfig().getBufferMode());
239    EXPECT_EQ(sizeof(TraceChunk), trace_log.getTraceConfig().getBufferSize());
240}
241
242TEST(TraceLogStaticTest, getInstance) {
243    EXPECT_EQ(&TraceLog::getInstance(), &TraceLog::getInstance());
244}
245
246/*
247 * It's slightly awkward to test if this actually does anything,
248 * so just run the code to check for memory leaks etc.
249 */
250TEST(TraceLogStaticTest, registerDeRegister) {
251    TraceLog trace_log;
252    trace_log.start(TraceConfig(BufferMode::fixed, sizeof(TraceChunk)));
253
254    // Cannot deregister without registering first
255    EXPECT_THROW(trace_log.deregisterThread(), std::logic_error);
256
257    // Cannot register twice
258    trace_log.registerThread();
259    EXPECT_THROW(trace_log.registerThread(), std::logic_error);
260
261    // Should be able to deregister after registering
262    EXPECT_NO_THROW(trace_log.deregisterThread());
263}
264
265TEST(TraceLogStaticTest, registerDeRegisterWithChunk) {
266    TraceLog trace_log;
267    trace_log.start(TraceConfig(BufferMode::fixed, sizeof(TraceChunk)));
268    trace_log.registerThread();
269    trace_log.logEvent(&tpi2, 0, 0);
270    EXPECT_NO_THROW(trace_log.deregisterThread());
271}
272
273struct DoneCallback : public TracingStoppedCallback {
274    bool invoked = false;
275
276    void operator()(TraceLog& log, std::lock_guard<TraceLog>& lh) override {
277        invoked = true;
278        EXPECT_NE(nullptr, log.getTraceContext(lh).getBuffer());
279    }
280};
281TEST_F(TraceLogTest, testDoneCallback) {
282
283    auto callback = std::make_shared<DoneCallback>();
284
285    trace_log.start(TraceConfig(BufferMode::fixed, min_buffer_size * 4)
286                        .setStoppedCallback(callback));
287
288    while (trace_log.isEnabled()) {
289        log_event();
290    }
291    // TraceLog should already be null
292    EXPECT_EQ(nullptr, trace_log.getTraceContext().getBuffer());
293    EXPECT_TRUE(callback->invoked);
294}
295
296TEST_F(TraceLogTest, nonBlockingStop) {
297    auto buffer = phosphor::utils::make_unique<MockTraceBuffer>();
298
299    auto* buffer_ptr = buffer.get();
300
301    // Return nullptr to indicate buffer is full
302    EXPECT_CALL(*buffer_ptr, getChunk())
303        .WillRepeatedly(testing::Return(nullptr));
304
305    trace_log.start(
306        TraceConfig([&buffer](size_t generation,
307                              size_t buffer_size) { return std::move(buffer); },
308                    min_buffer_size * 4));
309
310    {
311        std::lock_guard<TraceLog> lg(trace_log);
312
313        // Tracing shouldn't be stopped while lock is held separately
314        trace_log.logEvent(&tpi0, 0, 0);
315        EXPECT_TRUE(trace_log.isEnabled());
316    }
317
318    // Tracing should be stopped now that no one else is holding the lock
319    trace_log.logEvent(&tpi0, 0, 0);
320    EXPECT_FALSE(trace_log.isEnabled());
321}
322
323TEST_F(TraceLogTest, logExoticPointer) {
324    start_basic();
325
326    struct Exotic {};
327    Exotic e;
328
329    trace_log.logEvent(&tpi0, &e, 0);
330}
331
332TEST(TraceLogAltTest, FromEnvironmentConstructor) {
333    setenv("PHOSPHOR_TRACING_START", "buffer-mode:fixed;buffer-size:80000", 1);
334    TraceLog trace_log;
335    setenv("PHOSPHOR_TRACING_START", "", true);
336}
337
338struct DestructCallback : public TracingStoppedCallback {
339    bool invoked = false;
340
341    void operator()(TraceLog& log, std::lock_guard<TraceLog>& lh) override {
342        invoked = true;
343    }
344};
345TEST(TraceLogAltTest, stopOnDestruct) {
346    auto callback = std::make_shared<DestructCallback>();
347    {
348        TraceLog trace_log;
349        trace_log.start(TraceConfig(BufferMode::fixed, 80000)
350                            .setStoppedCallback(callback)
351                            .setStopTracingOnDestruct(true));
352    }
353    EXPECT_TRUE(callback->invoked);
354    callback->invoked = false;
355    {
356        TraceLog trace_log;
357        trace_log.start(TraceConfig(BufferMode::fixed, 80000)
358                            .setStoppedCallback(callback));
359    }
360    EXPECT_FALSE(callback->invoked);
361}
362
363TEST_F(TraceLogTest, RegisterDeregisterRegister) {
364
365    trace_log.deregisterThread();
366    trace_log.registerThread("name1");
367    auto context = trace_log.getTraceContext();
368    ASSERT_NE(0, context.getThreadNames().size());
369    auto it = context.getThreadNames().begin();
370    EXPECT_EQ("name1", it->second);
371
372    // Thread name shouldn't persist after de-registering when not running
373    trace_log.deregisterThread();
374    context = trace_log.getTraceContext();
375    EXPECT_EQ(0, context.getThreadNames().size());
376
377    // Thread name should persist even after de-registering when running
378    trace_log.registerThread("name1");
379    start_basic();
380    trace_log.deregisterThread();
381    trace_log.stop();
382    context = trace_log.getTraceContext();
383    ASSERT_NE(0, context.getThreadNames().size());
384    it = context.getThreadNames().begin();
385    EXPECT_EQ("name1", it->second);
386
387    // Registering a new name should override the old one
388    trace_log.registerThread("name2");
389    context = trace_log.getTraceContext();
390    ASSERT_NE(0, context.getThreadNames().size());
391    it = context.getThreadNames().begin();
392    EXPECT_EQ("name2", it->second);
393
394    // Thread names should be cleared by start
395    start_basic();
396    trace_log.deregisterThread();
397    trace_log.stop();
398    context = trace_log.getTraceContext();
399    EXPECT_NE(0, context.getThreadNames().size());
400    start_basic();
401    trace_log.stop();
402    context = trace_log.getTraceContext();
403    EXPECT_EQ(0, context.getThreadNames().size());
404
405    trace_log.registerThread();
406}
407
408TEST_F(TraceLogTest, StatsTest) {
409    using namespace testing;
410
411    NiceMock<MockStatsCallback> callback;
412
413    EXPECT_CALL(callback, callB(gsl_p::make_span("log_has_buffer"), false));
414    EXPECT_CALL(callback, callB(gsl_p::make_span("log_is_enabled"), false));
415
416    // we don't register/deregister any threads in this test so both should be 0
417    EXPECT_CALL(callback,
418                callU(gsl_p::make_span("log_thread_names"), 0));
419    EXPECT_CALL(callback,
420                callU(gsl_p::make_span("log_deregistered_threads"), 0));
421
422    // this is just the amount of groups the registry starts with by default
423    EXPECT_CALL(callback, callU(gsl_p::make_span("registry_group_count"), 3));
424
425    // PITA to check for correct values here so just make sure they exist
426    EXPECT_CALL(callback, callU(gsl_p::make_span("log_registered_tenants"), _));
427    trace_log.getStats(callback);
428    Mock::VerifyAndClearExpectations(&callback);
429
430    start_basic();
431    callback.expectAny();
432    EXPECT_CALL(callback, callB(gsl_p::make_span("log_has_buffer"), true));
433    EXPECT_CALL(callback, callB(gsl_p::make_span("log_is_enabled"), true));
434
435    // Check that we have at least one of the buffer stats
436    EXPECT_CALL(callback, callS(gsl_p::make_span("buffer_name"), _));
437    trace_log.getStats(callback);
438    Mock::VerifyAndClearExpectations(&callback);
439}
440