1 /* -*- Mode: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2 /*
3  *     Copyright 2017 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 "logger.h"
19 
20 #include <gtest/gtest.h>
21 #include <memcached/engine.h>
22 #include <memcached/extension.h>
23 #include <platform/cbassert.h>
24 #include <platform/dirutils.h>
25 #include <platform/memorymap.h>
26 #include <valgrind/valgrind.h>
27 
28 class SpdloggerTest : public ::testing::Test {
29 protected:
30 /*
31  * Unset a few environment variables which affect how the logger works.
32  * unsetenv() is not supported on Windows.
33  */
34 #ifndef WIN32
SetUpTestCase()35     static void SetUpTestCase() {
36         unsetenv("CB_MAXIMIZE_LOGGER_CYCLE_SIZE");
37         unsetenv("CB_MAXIMIZE_LOGGER_BUFFER_SIZE");
38     }
39 #endif
40 
41     void SetUp() override {
42         RemoveFiles();
43 
44         // We don't want to deal with multiple files in the
45         // basic tests. Set the file size to 20MB
46         SetUpLogger(20 * 1024);
47     }
48 
49     /**
50      * Set up the logger
51      *
52      * @param cyclesize - the size to use before switching file
53      */
SetUpLogger(size_t cyclesize)54     void SetUpLogger(size_t cyclesize) {
55         cb::logger::Config config;
56         config.filename = filename;
57         config.cyclesize = cyclesize;
58         config.buffersize = 8192;
59         config.unit_test = true;
60         config.console = false;
61 
62         const auto ret = cb::logger::initialize(config);
63         EXPECT_FALSE(ret) << ret.get();
64         cb::logger::get()->set_level(spdlog::level::level_enum::debug);
65     }
66 
RemoveFiles()67     void RemoveFiles() {
68         files = cb::io::findFilesWithPrefix(filename);
69         for (const auto& file : files) {
70             cb::io::rmrf(file);
71         }
72     }
73 
74     void TearDown() override {
75         cb::logger::shutdown();
76         RemoveFiles();
77     }
78 
getLogContents()79     std::string getLogContents() {
80         files = cb::io::findFilesWithPrefix(filename);
81         std::ostringstream ret;
82 
83         for (const auto& file : files) {
84             cb::MemoryMappedFile map(file.c_str(),
85                                      cb::MemoryMappedFile::Mode::RDONLY);
86             map.open();
87             ret << std::string{reinterpret_cast<const char*>(map.getRoot()),
88                                map.getSize()};
89         }
90 
91         return ret.str();
92     }
93 
94     std::vector<std::string> files;
95     const std::string filename{"spdlogger_test"};
96     const std::string openingHook = "---------- Opening logfile: ";
97     const std::string closingHook = "---------- Closing logfile";
98 };
99 
100 /**
101  * Helper function - counts how many times a string appears in a file.
102  *
103  * @param file the name of the file
104  * @param msg the message to searc hfor
105  * @return the number of times we found the message in the file
106  */
countInFile(const std::string& file, const std::string& msg)107 int countInFile(const std::string& file, const std::string& msg) {
108     cb::MemoryMappedFile map(file.c_str(), cb::MemoryMappedFile::Mode::RDONLY);
109     map.open();
110 
111     const auto* begin = reinterpret_cast<const char*>(map.getRoot());
112     const auto* end = begin + map.getSize();
113 
114     int count = 0;
115     while ((begin = std::search(begin, end, msg.begin(), msg.end())) != end) {
116         ++count;
117         begin += msg.size();
118     }
119     return count;
120 }
121 
122 /**
123  * Test that the printf-style of the logger still works
124  */
TEST_F(SpdloggerTest, OldStylePrintf)125 TEST_F(SpdloggerTest, OldStylePrintf) {
126     auto& logger = cb::logger::getLoggerDescriptor();
127     const uint32_t value = 0xdeadbeef;
128     logger.log(EXTENSION_LOG_INFO, nullptr, "OldStylePrintf %x", value);
129     cb::logger::shutdown();
130     files = cb::io::findFilesWithPrefix(filename);
131     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
132     EXPECT_EQ(1, countInFile(files.front(), "INFO OldStylePrintf deadbeef"));
133 }
134 
135 /**
136  * Test that the new fmt-style formatting works
137  */
TEST_F(SpdloggerTest, FmtStyleFormatting)138 TEST_F(SpdloggerTest, FmtStyleFormatting) {
139     const uint32_t value = 0xdeadbeef;
140     LOG_INFO("FmtStyleFormatting {:x}", value);
141     cb::logger::shutdown();
142     files = cb::io::findFilesWithPrefix(filename);
143     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
144     EXPECT_EQ(1,
145               countInFile(files.front(), "INFO FmtStyleFormatting deadbeef"));
146 }
147 
148 /**
149  * Tests writing the maximum allowed message to file. Messages are held in
150  * a buffer of size 2048, which allows for a message of size 2047 characters
151  * (excluding logger formatting and null terminator).
152  *
153  * (old printf style)
154  */
TEST_F(SpdloggerTest, LargeMessageTest)155 TEST_F(SpdloggerTest, LargeMessageTest) {
156     const std::string message(2047,
157                               'x'); // max message size is 2047 + 1 for '\0'
158     auto& logger = cb::logger::getLoggerDescriptor();
159     logger.log(EXTENSION_LOG_DEBUG, nullptr, message.c_str());
160     cb::logger::shutdown();
161 
162     files = cb::io::findFilesWithPrefix(filename);
163     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
164     EXPECT_EQ(1, countInFile(files.front(), message));
165 }
166 
167 /**
168  * Tests the message cropping feature.
169  * Crops a message which wouldn't fit in the message buffer.
170  *
171  * (old printf style)
172  */
TEST_F(SpdloggerTest, LargeMessageWithCroppingTest)173 TEST_F(SpdloggerTest, LargeMessageWithCroppingTest) {
174     const std::string message(2048, 'x'); // just 1 over max message size
175     std::string cropped(2047 - strlen(" [cut]"), 'x');
176     cropped.append(" [cut]");
177 
178     auto& logger = cb::logger::getLoggerDescriptor();
179     logger.log(EXTENSION_LOG_DEBUG, nullptr, message.c_str());
180     cb::logger::shutdown();
181 
182     files = cb::io::findFilesWithPrefix(filename);
183     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
184     EXPECT_EQ(1, countInFile(files.front(), cropped));
185 }
186 
187 /**
188  * Most basic test. Open a logfile, write a log message, close the logfile and
189  * check if the hooks appear in the file.
190  */
TEST_F(SpdloggerTest, BasicHooksTest)191 TEST_F(SpdloggerTest, BasicHooksTest) {
192     cb::logger::shutdown();
193 
194     files = cb::io::findFilesWithPrefix(filename);
195     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
196     EXPECT_EQ(1, countInFile(files.front(), openingHook));
197     EXPECT_EQ(1, countInFile(files.front(), closingHook));
198 }
199 
200 /**
201  * Test class for tests which wants to operate on multiple log files
202  *
203  * Initialize the logger with a 2k file rotation threshold
204  */
205 class FileRotationTest : public SpdloggerTest {
206 protected:
207     void SetUp() override {
208         RemoveFiles();
209         // Use a 2 k file size to make sure that we rotate :)
210         SetUpLogger(2048);
211     }
212 };
213 
214 /**
215  * Log multiple messages, which will causes the files to rotate a few times.
216  * Test if the hooks appear in each file.
217  */
TEST_F(FileRotationTest, MultipleFilesTest)218 TEST_F(FileRotationTest, MultipleFilesTest) {
219     const char* message =
220             "This is a textual log message that we want to repeat a number of "
221             "times: {}";
222     for (auto ii = 0; ii < 100; ii++) {
223         LOG_DEBUG(message, ii);
224     }
225     cb::logger::shutdown();
226 
227     files = cb::io::findFilesWithPrefix(filename);
228     EXPECT_LT(1, files.size());
229     for (auto& file : files) {
230         EXPECT_EQ(1, countInFile(file, openingHook))
231                 << "Missing open hook in file: " << file;
232         EXPECT_EQ(1, countInFile(file, closingHook))
233                 << "Missing closing hook in file: " << file;
234     }
235 }
236 
237 #ifndef WIN32
238 /**
239  * Test that it works as expected when running out of file
240  * descriptors. This test won't run on Windows as they don't
241  * have the same ulimit setting
242  */
TEST_F(FileRotationTest, HandleOpenFileErrors)243 TEST_F(FileRotationTest, HandleOpenFileErrors) {
244     if (RUNNING_ON_VALGRIND) {
245         std::cerr << "Skipping test when running on valgrind" << std::endl;
246         return;
247     }
248 
249 #ifdef UNDEFINED_SANITIZER
250     // MB-28735: This test fails under UBSan, when spdlog fails to open a new
251     // file (in custom_rotating_file_sink::_sink_it):
252     //
253     //     common.h:139:9: runtime error: member access within address <ADDR>
254     //     which does not point to an object of type 'spdlog::spdlog_ex' <ADDR>:
255     //     note: object has invalid vptr
256     //
257     // examing <ADDR> in a debugger indicates a valid object. Therefore skipping
258     // this test under UBSan.
259     std::cerr << "Skipping test when running on UBSan (MB-28735)\n";
260     return;
261 #endif
262 
263     LOG_DEBUG("Hey, this is a test");
264     cb::logger::flush();
265     files = cb::io::findFilesWithPrefix(filename);
266     EXPECT_EQ(1, files.size());
267 
268     // Bring down out open file limit to a more conservative level (to
269     // save using up a huge number of user / system FDs (and speed up the test).
270     rlimit rlim;
271     ASSERT_EQ(0, getrlimit(RLIMIT_NOFILE, &rlim))
272             << "Failed to get RLIMIT_NOFILE: " << strerror(errno);
273 
274     const auto current = rlim.rlim_cur;
275     rlim.rlim_cur = 100;
276     ASSERT_EQ(0, setrlimit(RLIMIT_NOFILE, &rlim))
277             << "Failed to set RLIMIT_NOFILE: " << strerror(errno);
278 
279     // Eat up file descriptors
280     std::vector<FILE*> fds;
281     FILE* fp;
282     while ((fp = fopen(files.front().c_str(), "r")) != nullptr) {
283         fds.push_back(fp);
284     }
285     EXPECT_EQ(EMFILE, errno);
286 
287     // Keep on logging. This should cause the files to wrap
288     const char* message =
289             "This is a textual log message that we want to repeat a number of "
290             "times {}";
291     for (auto ii = 0; ii < 100; ii++) {
292         LOG_DEBUG(message, ii);
293     }
294 
295     LOG_DEBUG("HandleOpenFileErrors");
296     cb::logger::flush();
297 
298     // We've just flushed the data to the file, so it should be possible
299     // to find it in the file.
300     char buffer[1024];
301     bool found = false;
302     while (fgets(buffer, sizeof(buffer), fds.front()) != nullptr) {
303         if (strstr(buffer, "HandleOpenFileErrors") != nullptr) {
304             found = true;
305         }
306     }
307 
308     EXPECT_TRUE(found) << files.front()
309                        << " does not contain HandleOpenFileErrors";
310 
311     // close all of the file descriptors
312     for (const auto& fp : fds) {
313         fclose(fp);
314     }
315     fds.clear();
316 
317     // Verify that we didn't get a new file while we didn't have any
318     // free file descriptors
319     files = cb::io::findFilesWithPrefix(filename);
320     EXPECT_EQ(1, files.size());
321 
322     // Add a log entry, and we should get a new file
323     LOG_DEBUG("Logging to the next file");
324     cb::logger::flush();
325 
326     files = cb::io::findFilesWithPrefix(filename);
327     EXPECT_EQ(2, files.size());
328 
329     // Restore the filedescriptors
330     rlim.rlim_cur = current;
331     ASSERT_EQ(0, setrlimit(RLIMIT_NOFILE, &rlim))
332             << "Failed to restore RLIMIT_NOFILE: " << strerror(errno);
333 }
334 #endif
335