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