1 /* -*- Mode: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2 /*
3  *     Copyright 2018 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_test_fixture.h"
19 
20 #include <memcached/engine.h>
21 #include <platform/cbassert.h>
22 
23 #include <valgrind/valgrind.h>
24 
25 #ifndef WIN32
26 #include <sys/resource.h>
27 #endif
28 
29 /**
30  * Test that the new fmt-style formatting works
31  */
TEST_F(SpdloggerTest, FmtStyleFormatting)32 TEST_F(SpdloggerTest, FmtStyleFormatting) {
33     const uint32_t value = 0xdeadbeef;
34     LOG_INFO("FmtStyleFormatting {:x}", value);
35     cb::logger::shutdown();
36     files = cb::io::findFilesWithPrefix(config.filename);
37     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
38     EXPECT_EQ(1,
39               countInFile(files.front(), "INFO FmtStyleFormatting deadbeef"));
40 }
41 
42 /**
43  * Most basic test. Open a logfile, write a log message, close the logfile and
44  * check if the hooks appear in the file.
45  */
TEST_F(SpdloggerTest, BasicHooksTest)46 TEST_F(SpdloggerTest, BasicHooksTest) {
47     cb::logger::shutdown();
48 
49     files = cb::io::findFilesWithPrefix(config.filename);
50     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
51     EXPECT_EQ(1, countInFile(files.front(), openingHook));
52     EXPECT_EQ(1, countInFile(files.front(), closingHook));
53 }
54 
55 /**
56  * Test class for tests which wants to operate on multiple log files
57  *
58  * Initialize the logger with a 2k file rotation threshold
59  */
60 class FileRotationTest : public SpdloggerTest {
61 protected:
62     void SetUp() override {
63         RemoveFiles();
64         // Use a 2 k file size to make sure that we rotate :)
65         config.log_level = spdlog::level::level_enum::debug;
66         config.cyclesize = 2048;
67         setUpLogger();
68     }
69 };
70 
71 /**
72  * Log multiple messages, which will causes the files to rotate a few times.
73  * Test if the hooks appear in each file.
74  */
TEST_F(FileRotationTest, MultipleFilesTest)75 TEST_F(FileRotationTest, MultipleFilesTest) {
76     const char* message =
77             "This is a textual log message that we want to repeat a number of "
78             "times: {}";
79     for (auto ii = 0; ii < 100; ii++) {
80         LOG_DEBUG(message, ii);
81     }
82     cb::logger::shutdown();
83 
84     files = cb::io::findFilesWithPrefix(config.filename);
85     EXPECT_LT(1, files.size());
86     for (auto& file : files) {
87         EXPECT_EQ(1, countInFile(file, openingHook))
88                 << "Missing open hook in file: " << file;
89         EXPECT_EQ(1, countInFile(file, closingHook))
90                 << "Missing closing hook in file: " << file;
91     }
92 }
93 
94 #ifndef WIN32
95 /**
96  * Test that it works as expected when running out of file
97  * descriptors. This test won't run on Windows as they don't
98  * have the same ulimit setting
99  */
TEST_F(FileRotationTest, HandleOpenFileErrors)100 TEST_F(FileRotationTest, HandleOpenFileErrors) {
101     if (RUNNING_ON_VALGRIND) {
102         std::cerr << "Skipping test when running on valgrind" << std::endl;
103         return;
104     }
105 
106 #ifdef UNDEFINED_SANITIZER
107     // MB-28735: This test fails under UBSan, when spdlog fails to open a new
108     // file (in custom_rotating_file_sink::_sink_it):
109     //
110     //     common.h:139:9: runtime error: member access within address <ADDR>
111     //     which does not point to an object of type 'spdlog::spdlog_ex' <ADDR>:
112     //     note: object has invalid vptr
113     //
114     // examing <ADDR> in a debugger indicates a valid object. Therefore skipping
115     // this test under UBSan.
116     std::cerr << "Skipping test when running on UBSan (MB-28735)\n";
117     return;
118 #endif
119 
120     LOG_DEBUG("Hey, this is a test");
121     cb::logger::flush();
122     files = cb::io::findFilesWithPrefix(config.filename);
123     EXPECT_EQ(1, files.size());
124 
125     // Bring down out open file limit to a more conservative level (to
126     // save using up a huge number of user / system FDs (and speed up the test).
127     rlimit rlim;
128     ASSERT_EQ(0, getrlimit(RLIMIT_NOFILE, &rlim))
129             << "Failed to get RLIMIT_NOFILE: " << strerror(errno);
130 
131     const auto current = rlim.rlim_cur;
132     rlim.rlim_cur = 100;
133     ASSERT_EQ(0, setrlimit(RLIMIT_NOFILE, &rlim))
134             << "Failed to set RLIMIT_NOFILE: " << strerror(errno);
135 
136     // Eat up file descriptors
137     std::vector<FILE*> fds;
138     FILE* fp;
139     while ((fp = fopen(files.front().c_str(), "r")) != nullptr) {
140         fds.push_back(fp);
141     }
142     EXPECT_EQ(EMFILE, errno);
143 
144     // Keep on logging. This should cause the files to wrap
145     const char* message =
146             "This is a textual log message that we want to repeat a number of "
147             "times {}";
148     for (auto ii = 0; ii < 100; ii++) {
149         LOG_DEBUG(message, ii);
150     }
151 
152     LOG_DEBUG("HandleOpenFileErrors");
153     cb::logger::flush();
154 
155     // We've just flushed the data to the file, so it should be possible
156     // to find it in the file.
157     char buffer[1024];
158     bool found = false;
159     while (fgets(buffer, sizeof(buffer), fds.front()) != nullptr) {
160         if (strstr(buffer, "HandleOpenFileErrors") != nullptr) {
161             found = true;
162         }
163     }
164 
165     EXPECT_TRUE(found) << files.front()
166                        << " does not contain HandleOpenFileErrors";
167 
168     // close all of the file descriptors
169     for (const auto& fp : fds) {
170         fclose(fp);
171     }
172     fds.clear();
173 
174     // Verify that we didn't get a new file while we didn't have any
175     // free file descriptors
176     files = cb::io::findFilesWithPrefix(config.filename);
177     EXPECT_EQ(1, files.size());
178 
179     // Add a log entry, and we should get a new file
180     LOG_DEBUG("Logging to the next file");
181     cb::logger::flush();
182 
183     files = cb::io::findFilesWithPrefix(config.filename);
184     EXPECT_EQ(2, files.size());
185 
186     // Restore the filedescriptors
187     rlim.rlim_cur = current;
188     ASSERT_EQ(0, setrlimit(RLIMIT_NOFILE, &rlim))
189             << "Failed to restore RLIMIT_NOFILE: " << strerror(errno);
190 }
191 #endif
192 
193 /**
194  * Test that the custom type Vbid (see memcached/vbucket.h) performs
195  * its prefixing successfully whenever outputting a vBucket ID
196  */
TEST_F(SpdloggerTest, VbidClassTest)197 TEST_F(SpdloggerTest, VbidClassTest) {
198     const Vbid value = Vbid(1023);
199     LOG_INFO("VbidClassTest {}", value);
200     cb::logger::shutdown();
201     files = cb::io::findFilesWithPrefix(config.filename);
202     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
203     EXPECT_EQ(1, countInFile(files.front(), "INFO VbidClassTest vb:1023"));
204 }
205 
206 /**
207  * MB-32688: Missing final log entries just before crash (or shutdown).
208  *
209  * Test that everything we attempt to log before we call shutdown is actually
210  * flushed to a file.
211  *
212  * Test MAY pass if this race condition is present. Runtime is tuned for CV
213  * machines which are generally much slower than dev machines. Anecdotal -
214  * false positive rate on my dev machine (MB Pro 2017 - PCIe SSD) is ~1/1000.
215  * This SHOULD be lower on CV machines as the flush command will take much
216  * longer to execute (slower disks) which will back the file logger up more. Any
217  * sporadic failures of this test likely mean a reintroduction of this race
218  * condition and should be investigated.
219  */
TEST_F(SpdloggerTest, ShutdownRace)220 TEST_F(SpdloggerTest, ShutdownRace) {
221     // We need the async logger for this test, shutdown the existing one and
222     // create it.
223     cb::logger::shutdown();
224     RemoveFiles();
225     config.unit_test = false;
226     setUpLogger();
227 
228     // Back the file logger up with messages and flush commands.
229     for (int i = 0; i < 100; i++) {
230         // Post messages to the async logger - doesn't actually perform a flush,
231         // but queues one on the async logger
232         LOG_CRITICAL("a message");
233         cb::logger::flush();
234     }
235 
236     LOG_CRITICAL("We should see this msg");
237     LOG_CRITICAL("and this one");
238     // And this very long one
239     auto str = std::string(50000, 'a');
240     LOG_CRITICAL("{}", str);
241 
242     // Shutdown, process all messages in the queue, then return.
243     cb::logger::shutdown();
244     files = cb::io::findFilesWithPrefix(config.filename);
245     ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
246     EXPECT_EQ(1, countInFile(files.front(), "CRITICAL We should see this msg"));
247     EXPECT_EQ(1, countInFile(files.front(), "CRITICAL and this one"));
248     EXPECT_EQ(1, countInFile(files.front(), "CRITICAL " + str));
249 }
250