17396ee9cSEugen-Alexandru Virtan/* -*- Mode: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
27396ee9cSEugen-Alexandru Virtan/*
37396ee9cSEugen-Alexandru Virtan *     Copyright 2017 Couchbase, Inc
47396ee9cSEugen-Alexandru Virtan *
57396ee9cSEugen-Alexandru Virtan *   Licensed under the Apache License, Version 2.0 (the "License");
67396ee9cSEugen-Alexandru Virtan *   you may not use this file except in compliance with the License.
77396ee9cSEugen-Alexandru Virtan *   You may obtain a copy of the License at
87396ee9cSEugen-Alexandru Virtan *
97396ee9cSEugen-Alexandru Virtan *       http://www.apache.org/licenses/LICENSE-2.0
107396ee9cSEugen-Alexandru Virtan *
117396ee9cSEugen-Alexandru Virtan *   Unless required by applicable law or agreed to in writing, software
127396ee9cSEugen-Alexandru Virtan *   distributed under the License is distributed on an "AS IS" BASIS,
137396ee9cSEugen-Alexandru Virtan *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
147396ee9cSEugen-Alexandru Virtan *   See the License for the specific language governing permissions and
157396ee9cSEugen-Alexandru Virtan *   limitations under the License.
167396ee9cSEugen-Alexandru Virtan */
177396ee9cSEugen-Alexandru Virtan
1814052deaSTrond Norbye#include "logger.h"
197396ee9cSEugen-Alexandru Virtan
207396ee9cSEugen-Alexandru Virtan#include <gtest/gtest.h>
219d5eebd4STrond Norbye#include <memcached/engine.h>
2214052deaSTrond Norbye#include <memcached/extension.h>
2314052deaSTrond Norbye#include <platform/cbassert.h>
247396ee9cSEugen-Alexandru Virtan#include <platform/dirutils.h>
256410dc5bSTrond Norbye#include <platform/memorymap.h>
2661f006adSTrond Norbye#include <valgrind/valgrind.h>
277396ee9cSEugen-Alexandru Virtan
287396ee9cSEugen-Alexandru Virtanclass SpdloggerTest : public ::testing::Test {
297396ee9cSEugen-Alexandru Virtanprotected:
307396ee9cSEugen-Alexandru Virtan/*
317396ee9cSEugen-Alexandru Virtan * Unset a few environment variables which affect how the logger works.
327396ee9cSEugen-Alexandru Virtan * unsetenv() is not supported on Windows.
337396ee9cSEugen-Alexandru Virtan */
347396ee9cSEugen-Alexandru Virtan#ifndef WIN32
357396ee9cSEugen-Alexandru Virtan    static void SetUpTestCase() {
367396ee9cSEugen-Alexandru Virtan        unsetenv("CB_MAXIMIZE_LOGGER_CYCLE_SIZE");
377396ee9cSEugen-Alexandru Virtan        unsetenv("CB_MAXIMIZE_LOGGER_BUFFER_SIZE");
387396ee9cSEugen-Alexandru Virtan    }
397396ee9cSEugen-Alexandru Virtan#endif
407396ee9cSEugen-Alexandru Virtan
4114052deaSTrond Norbye    void SetUp() override {
4214052deaSTrond Norbye        RemoveFiles();
437396ee9cSEugen-Alexandru Virtan
44fd6bfd4cSTrond Norbye        // We don't want to deal with multiple files in the
45fd6bfd4cSTrond Norbye        // basic tests. Set the file size to 20MB
46fd6bfd4cSTrond Norbye        SetUpLogger(20 * 1024);
47fd6bfd4cSTrond Norbye    }
48fd6bfd4cSTrond Norbye
49fd6bfd4cSTrond Norbye    /**
50fd6bfd4cSTrond Norbye     * Set up the logger
51fd6bfd4cSTrond Norbye     *
52fd6bfd4cSTrond Norbye     * @param cyclesize - the size to use before switching file
53fd6bfd4cSTrond Norbye     */
54fd6bfd4cSTrond Norbye    void SetUpLogger(size_t cyclesize) {
5514052deaSTrond Norbye        cb::logger::Config config;
5614052deaSTrond Norbye        config.filename = filename;
57fd6bfd4cSTrond Norbye        config.cyclesize = cyclesize;
587396ee9cSEugen-Alexandru Virtan        config.buffersize = 8192;
597396ee9cSEugen-Alexandru Virtan        config.unit_test = true;
60c5430f6dSEugen-Alexandru Virtan        config.console = false;
617396ee9cSEugen-Alexandru Virtan
620ee65ef1STrond Norbye        const auto ret = cb::logger::initialize(config);
6314052deaSTrond Norbye        EXPECT_FALSE(ret) << ret.get();
640ee65ef1STrond Norbye        cb::logger::get()->set_level(spdlog::level::level_enum::debug);
6514052deaSTrond Norbye    }
6614052deaSTrond Norbye
6714052deaSTrond Norbye    void RemoveFiles() {
6814052deaSTrond Norbye        files = cb::io::findFilesWithPrefix(filename);
69114a3f3aSTrond Norbye        for (const auto& file : files) {
7014052deaSTrond Norbye            cb::io::rmrf(file);
7114052deaSTrond Norbye        }
727396ee9cSEugen-Alexandru Virtan    }
7314052deaSTrond Norbye
74c5430f6dSEugen-Alexandru Virtan    void TearDown() override {
754d6fdda3STrond Norbye        cb::logger::shutdown();
76c5430f6dSEugen-Alexandru Virtan        RemoveFiles();
77c5430f6dSEugen-Alexandru Virtan    }
78c5430f6dSEugen-Alexandru Virtan
79fd6bfd4cSTrond Norbye    std::string getLogContents() {
80fd6bfd4cSTrond Norbye        files = cb::io::findFilesWithPrefix(filename);
81fd6bfd4cSTrond Norbye        std::ostringstream ret;
82fd6bfd4cSTrond Norbye
83fd6bfd4cSTrond Norbye        for (const auto& file : files) {
84fd6bfd4cSTrond Norbye            cb::MemoryMappedFile map(file.c_str(),
85fd6bfd4cSTrond Norbye                                     cb::MemoryMappedFile::Mode::RDONLY);
86fd6bfd4cSTrond Norbye            map.open();
87fd6bfd4cSTrond Norbye            ret << std::string{reinterpret_cast<const char*>(map.getRoot()),
88fd6bfd4cSTrond Norbye                               map.getSize()};
89fd6bfd4cSTrond Norbye        }
90fd6bfd4cSTrond Norbye
91fd6bfd4cSTrond Norbye        return ret.str();
92fd6bfd4cSTrond Norbye    }
93fd6bfd4cSTrond Norbye
947396ee9cSEugen-Alexandru Virtan    std::vector<std::string> files;
9514052deaSTrond Norbye    const std::string filename{"spdlogger_test"};
9614052deaSTrond Norbye    const std::string openingHook = "---------- Opening logfile: ";
9714052deaSTrond Norbye    const std::string closingHook = "---------- Closing logfile";
987396ee9cSEugen-Alexandru Virtan};
997396ee9cSEugen-Alexandru Virtan
1006410dc5bSTrond Norbye/**
1016410dc5bSTrond Norbye * Helper function - counts how many times a string appears in a file.
1026410dc5bSTrond Norbye *
1036410dc5bSTrond Norbye * @param file the name of the file
1046410dc5bSTrond Norbye * @param msg the message to searc hfor
1056410dc5bSTrond Norbye * @return the number of times we found the message in the file
1066410dc5bSTrond Norbye */
1077396ee9cSEugen-Alexandru Virtanint countInFile(const std::string& file, const std::string& msg) {
1086410dc5bSTrond Norbye    cb::MemoryMappedFile map(file.c_str(), cb::MemoryMappedFile::Mode::RDONLY);
1096410dc5bSTrond Norbye    map.open();
1107396ee9cSEugen-Alexandru Virtan
1116410dc5bSTrond Norbye    const auto* begin = reinterpret_cast<const char*>(map.getRoot());
1126410dc5bSTrond Norbye    const auto* end = begin + map.getSize();
1137396ee9cSEugen-Alexandru Virtan
1146410dc5bSTrond Norbye    int count = 0;
1156410dc5bSTrond Norbye    while ((begin = std::search(begin, end, msg.begin(), msg.end())) != end) {
1166410dc5bSTrond Norbye        ++count;
1176410dc5bSTrond Norbye        begin += msg.size();
1187396ee9cSEugen-Alexandru Virtan    }
1197396ee9cSEugen-Alexandru Virtan    return count;
1207396ee9cSEugen-Alexandru Virtan}
1217396ee9cSEugen-Alexandru Virtan
122e1aff694STrond Norbye/**
123e1aff694STrond Norbye * Test that the printf-style of the logger still works
124e1aff694STrond Norbye */
125e1aff694STrond NorbyeTEST_F(SpdloggerTest, OldStylePrintf) {
126114a3f3aSTrond Norbye    auto& logger = cb::logger::getLoggerDescriptor();
127e1aff694STrond Norbye    const uint32_t value = 0xdeadbeef;
128114a3f3aSTrond Norbye    logger.log(EXTENSION_LOG_INFO, nullptr, "OldStylePrintf %x", value);
129e1aff694STrond Norbye    cb::logger::shutdown();
130e1aff694STrond Norbye    files = cb::io::findFilesWithPrefix(filename);
131fd6bfd4cSTrond Norbye    ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
132e1aff694STrond Norbye    EXPECT_EQ(1, countInFile(files.front(), "INFO OldStylePrintf deadbeef"));
133e1aff694STrond Norbye}
134e1aff694STrond Norbye
135e1aff694STrond Norbye/**
136e1aff694STrond Norbye * Test that the new fmt-style formatting works
137e1aff694STrond Norbye */
138e1aff694STrond NorbyeTEST_F(SpdloggerTest, FmtStyleFormatting) {
139e1aff694STrond Norbye    const uint32_t value = 0xdeadbeef;
140e1aff694STrond Norbye    LOG_INFO("FmtStyleFormatting {:x}", value);
141e1aff694STrond Norbye    cb::logger::shutdown();
142e1aff694STrond Norbye    files = cb::io::findFilesWithPrefix(filename);
143fd6bfd4cSTrond Norbye    ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
144e1aff694STrond Norbye    EXPECT_EQ(1,
145e1aff694STrond Norbye              countInFile(files.front(), "INFO FmtStyleFormatting deadbeef"));
146e1aff694STrond Norbye}
147e1aff694STrond Norbye
14814052deaSTrond Norbye/**
14914052deaSTrond Norbye * Tests writing the maximum allowed message to file. Messages are held in
1507396ee9cSEugen-Alexandru Virtan * a buffer of size 2048, which allows for a message of size 2047 characters
1517396ee9cSEugen-Alexandru Virtan * (excluding logger formatting and null terminator).
152114a3f3aSTrond Norbye *
153114a3f3aSTrond Norbye * (old printf style)
1547396ee9cSEugen-Alexandru Virtan */
1557396ee9cSEugen-Alexandru VirtanTEST_F(SpdloggerTest, LargeMessageTest) {
156114a3f3aSTrond Norbye    const std::string message(2047,
157114a3f3aSTrond Norbye                              'x'); // max message size is 2047 + 1 for '\0'
158114a3f3aSTrond Norbye    auto& logger = cb::logger::getLoggerDescriptor();
159114a3f3aSTrond Norbye    logger.log(EXTENSION_LOG_DEBUG, nullptr, message.c_str());
1604d6fdda3STrond Norbye    cb::logger::shutdown();
1617396ee9cSEugen-Alexandru Virtan
16214052deaSTrond Norbye    files = cb::io::findFilesWithPrefix(filename);
163fd6bfd4cSTrond Norbye    ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
164fd6bfd4cSTrond Norbye    EXPECT_EQ(1, countInFile(files.front(), message));
1657396ee9cSEugen-Alexandru Virtan}
1667396ee9cSEugen-Alexandru Virtan
16714052deaSTrond Norbye/**
16814052deaSTrond Norbye * Tests the message cropping feature.
1697396ee9cSEugen-Alexandru Virtan * Crops a message which wouldn't fit in the message buffer.
170114a3f3aSTrond Norbye *
171114a3f3aSTrond Norbye * (old printf style)
1727396ee9cSEugen-Alexandru Virtan */
1737396ee9cSEugen-Alexandru VirtanTEST_F(SpdloggerTest, LargeMessageWithCroppingTest) {
174114a3f3aSTrond Norbye    const std::string message(2048, 'x'); // just 1 over max message size
1757396ee9cSEugen-Alexandru Virtan    std::string cropped(2047 - strlen(" [cut]"), 'x');
1767396ee9cSEugen-Alexandru Virtan    cropped.append(" [cut]");
1777396ee9cSEugen-Alexandru Virtan
178114a3f3aSTrond Norbye    auto& logger = cb::logger::getLoggerDescriptor();
179114a3f3aSTrond Norbye    logger.log(EXTENSION_LOG_DEBUG, nullptr, message.c_str());
1804d6fdda3STrond Norbye    cb::logger::shutdown();
1817396ee9cSEugen-Alexandru Virtan
182114a3f3aSTrond Norbye    files = cb::io::findFilesWithPrefix(filename);
183fd6bfd4cSTrond Norbye    ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
184fd6bfd4cSTrond Norbye    EXPECT_EQ(1, countInFile(files.front(), cropped));
18514052deaSTrond Norbye}
1867396ee9cSEugen-Alexandru Virtan
18714052deaSTrond Norbye/**
18814052deaSTrond Norbye * Most basic test. Open a logfile, write a log message, close the logfile and
1897396ee9cSEugen-Alexandru Virtan * check if the hooks appear in the file.
1907396ee9cSEugen-Alexandru Virtan */
19114052deaSTrond NorbyeTEST_F(SpdloggerTest, BasicHooksTest) {
1924d6fdda3STrond Norbye    cb::logger::shutdown();
1937396ee9cSEugen-Alexandru Virtan
1947396ee9cSEugen-Alexandru Virtan    files = cb::io::findFilesWithPrefix(filename);
195fd6bfd4cSTrond Norbye    ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
196114a3f3aSTrond Norbye    EXPECT_EQ(1, countInFile(files.front(), openingHook));
197114a3f3aSTrond Norbye    EXPECT_EQ(1, countInFile(files.front(), closingHook));
1987396ee9cSEugen-Alexandru Virtan}
1997396ee9cSEugen-Alexandru Virtan
200fd6bfd4cSTrond Norbye/**
201fd6bfd4cSTrond Norbye * Test class for tests which wants to operate on multiple log files
202fd6bfd4cSTrond Norbye *
203fd6bfd4cSTrond Norbye * Initialize the logger with a 2k file rotation threshold
204fd6bfd4cSTrond Norbye */
205fd6bfd4cSTrond Norbyeclass FileRotationTest : public SpdloggerTest {
206fd6bfd4cSTrond Norbyeprotected:
207fd6bfd4cSTrond Norbye    void SetUp() override {
208fd6bfd4cSTrond Norbye        RemoveFiles();
209fd6bfd4cSTrond Norbye        // Use a 2 k file size to make sure that we rotate :)
210fd6bfd4cSTrond Norbye        SetUpLogger(2048);
211fd6bfd4cSTrond Norbye    }
212fd6bfd4cSTrond Norbye};
213fd6bfd4cSTrond Norbye
21414052deaSTrond Norbye/**
21514052deaSTrond Norbye * Log multiple messages, which will causes the files to rotate a few times.
2167396ee9cSEugen-Alexandru Virtan * Test if the hooks appear in each file.
2177396ee9cSEugen-Alexandru Virtan */
218fd6bfd4cSTrond NorbyeTEST_F(FileRotationTest, MultipleFilesTest) {
219114a3f3aSTrond Norbye    const char* message =
22014052deaSTrond Norbye            "This is a textual log message that we want to repeat a number of "
221114a3f3aSTrond Norbye            "times: {}";
22214052deaSTrond Norbye    for (auto ii = 0; ii < 100; ii++) {
223114a3f3aSTrond Norbye        LOG_DEBUG(message, ii);
2247396ee9cSEugen-Alexandru Virtan    }
2254d6fdda3STrond Norbye    cb::logger::shutdown();
2267396ee9cSEugen-Alexandru Virtan
2277396ee9cSEugen-Alexandru Virtan    files = cb::io::findFilesWithPrefix(filename);
2287396ee9cSEugen-Alexandru Virtan    EXPECT_LT(1, files.size());
229114a3f3aSTrond Norbye    for (auto& file : files) {
230114a3f3aSTrond Norbye        EXPECT_EQ(1, countInFile(file, openingHook))
231114a3f3aSTrond Norbye                << "Missing open hook in file: " << file;
232114a3f3aSTrond Norbye        EXPECT_EQ(1, countInFile(file, closingHook))
233114a3f3aSTrond Norbye                << "Missing closing hook in file: " << file;
2347396ee9cSEugen-Alexandru Virtan    }
2357396ee9cSEugen-Alexandru Virtan}
23661f006adSTrond Norbye
23761f006adSTrond Norbye#ifndef WIN32
23861f006adSTrond Norbye/**
23961f006adSTrond Norbye * Test that it works as expected when running out of file
24061f006adSTrond Norbye * descriptors. This test won't run on Windows as they don't
24161f006adSTrond Norbye * have the same ulimit setting
24261f006adSTrond Norbye */
243fd6bfd4cSTrond NorbyeTEST_F(FileRotationTest, HandleOpenFileErrors) {
24461f006adSTrond Norbye    if (RUNNING_ON_VALGRIND) {
245114a3f3aSTrond Norbye        std::cerr << "Skipping test when running on valgrind" << std::endl;
24661f006adSTrond Norbye        return;
24761f006adSTrond Norbye    }
24861f006adSTrond Norbye
249e7a2eb2aSDave Rigby#ifdef UNDEFINED_SANITIZER
250e7a2eb2aSDave Rigby    // MB-28735: This test fails under UBSan, when spdlog fails to open a new
251e7a2eb2aSDave Rigby    // file (in custom_rotating_file_sink::_sink_it):
252e7a2eb2aSDave Rigby    //
253e7a2eb2aSDave Rigby    //     common.h:139:9: runtime error: member access within address <ADDR>
254e7a2eb2aSDave Rigby    //     which does not point to an object of type 'spdlog::spdlog_ex' <ADDR>:
255e7a2eb2aSDave Rigby    //     note: object has invalid vptr
256e7a2eb2aSDave Rigby    //
257e7a2eb2aSDave Rigby    // examing <ADDR> in a debugger indicates a valid object. Therefore skipping
258e7a2eb2aSDave Rigby    // this test under UBSan.
259e7a2eb2aSDave Rigby    std::cerr << "Skipping test when running on UBSan (MB-28735)\n";
260e7a2eb2aSDave Rigby    return;
261e7a2eb2aSDave Rigby#endif
262e7a2eb2aSDave Rigby
263114a3f3aSTrond Norbye    LOG_DEBUG("Hey, this is a test");
2644d6fdda3STrond Norbye    cb::logger::flush();
26561f006adSTrond Norbye    files = cb::io::findFilesWithPrefix(filename);
26661f006adSTrond Norbye    EXPECT_EQ(1, files.size());
26761f006adSTrond Norbye
26861f006adSTrond Norbye    // Bring down out open file limit to a more conservative level (to
26961f006adSTrond Norbye    // save using up a huge number of user / system FDs (and speed up the test).
27061f006adSTrond Norbye    rlimit rlim;
27161f006adSTrond Norbye    ASSERT_EQ(0, getrlimit(RLIMIT_NOFILE, &rlim))
27261f006adSTrond Norbye            << "Failed to get RLIMIT_NOFILE: " << strerror(errno);
27361f006adSTrond Norbye
27461f006adSTrond Norbye    const auto current = rlim.rlim_cur;
27561f006adSTrond Norbye    rlim.rlim_cur = 100;
27661f006adSTrond Norbye    ASSERT_EQ(0, setrlimit(RLIMIT_NOFILE, &rlim))
27761f006adSTrond Norbye            << "Failed to set RLIMIT_NOFILE: " << strerror(errno);
27861f006adSTrond Norbye
27961f006adSTrond Norbye    // Eat up file descriptors
28061f006adSTrond Norbye    std::vector<FILE*> fds;
28161f006adSTrond Norbye    FILE* fp;
28261f006adSTrond Norbye    while ((fp = fopen(files.front().c_str(), "r")) != nullptr) {
28361f006adSTrond Norbye        fds.push_back(fp);
28461f006adSTrond Norbye    }
28561f006adSTrond Norbye    EXPECT_EQ(EMFILE, errno);
28661f006adSTrond Norbye
28761f006adSTrond Norbye    // Keep on logging. This should cause the files to wrap
288114a3f3aSTrond Norbye    const char* message =
28961f006adSTrond Norbye            "This is a textual log message that we want to repeat a number of "
290114a3f3aSTrond Norbye            "times {}";
29161f006adSTrond Norbye    for (auto ii = 0; ii < 100; ii++) {
292114a3f3aSTrond Norbye        LOG_DEBUG(message, ii);
29361f006adSTrond Norbye    }
29461f006adSTrond Norbye
295114a3f3aSTrond Norbye    LOG_DEBUG("HandleOpenFileErrors");
2964d6fdda3STrond Norbye    cb::logger::flush();
29761f006adSTrond Norbye
29861f006adSTrond Norbye    // We've just flushed the data to the file, so it should be possible
29961f006adSTrond Norbye    // to find it in the file.
30061f006adSTrond Norbye    char buffer[1024];
30161f006adSTrond Norbye    bool found = false;
30261f006adSTrond Norbye    while (fgets(buffer, sizeof(buffer), fds.front()) != nullptr) {
30361f006adSTrond Norbye        if (strstr(buffer, "HandleOpenFileErrors") != nullptr) {
30461f006adSTrond Norbye            found = true;
30561f006adSTrond Norbye        }
30661f006adSTrond Norbye    }
30761f006adSTrond Norbye
30861f006adSTrond Norbye    EXPECT_TRUE(found) << files.front()
30961f006adSTrond Norbye                       << " does not contain HandleOpenFileErrors";
31061f006adSTrond Norbye
31161f006adSTrond Norbye    // close all of the file descriptors
31261f006adSTrond Norbye    for (const auto& fp : fds) {
31361f006adSTrond Norbye        fclose(fp);
31461f006adSTrond Norbye    }
31561f006adSTrond Norbye    fds.clear();
31661f006adSTrond Norbye
31761f006adSTrond Norbye    // Verify that we didn't get a new file while we didn't have any
31861f006adSTrond Norbye    // free file descriptors
31961f006adSTrond Norbye    files = cb::io::findFilesWithPrefix(filename);
32061f006adSTrond Norbye    EXPECT_EQ(1, files.size());
32161f006adSTrond Norbye
32261f006adSTrond Norbye    // Add a log entry, and we should get a new file
323114a3f3aSTrond Norbye    LOG_DEBUG("Logging to the next file");
3244d6fdda3STrond Norbye    cb::logger::flush();
32561f006adSTrond Norbye
32661f006adSTrond Norbye    files = cb::io::findFilesWithPrefix(filename);
32761f006adSTrond Norbye    EXPECT_EQ(2, files.size());
32861f006adSTrond Norbye
32961f006adSTrond Norbye    // Restore the filedescriptors
33061f006adSTrond Norbye    rlim.rlim_cur = current;
33161f006adSTrond Norbye    ASSERT_EQ(0, setrlimit(RLIMIT_NOFILE, &rlim))
33261f006adSTrond Norbye            << "Failed to restore RLIMIT_NOFILE: " << strerror(errno);
33361f006adSTrond Norbye}
33461f006adSTrond Norbye#endif
335