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