1 | //===-- LogTest.cpp -------------------------------------------------------===// |
2 | // |
3 | // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions. |
4 | // See https://llvm.org/LICENSE.txt for license information. |
5 | // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception |
6 | // |
7 | //===----------------------------------------------------------------------===// |
8 | |
9 | #include "gmock/gmock.h" |
10 | #include "gtest/gtest.h" |
11 | |
12 | #include "lldb/Utility/Log.h" |
13 | #include "lldb/Utility/StreamString.h" |
14 | #include "llvm/ADT/BitmaskEnum.h" |
15 | #include "llvm/Support/ManagedStatic.h" |
16 | #include "llvm/Support/Threading.h" |
17 | #include <thread> |
18 | |
19 | using namespace lldb; |
20 | using namespace lldb_private; |
21 | |
22 | enum class TestChannel : Log::MaskType { |
23 | FOO = Log::ChannelFlag<0>, |
24 | BAR = Log::ChannelFlag<1>, |
25 | LLVM_MARK_AS_BITMASK_ENUM(BAR), |
26 | }; |
27 | |
28 | LLVM_ENABLE_BITMASK_ENUMS_IN_NAMESPACE(); |
29 | |
30 | static constexpr Log::Category test_categories[] = { |
31 | {{"foo" }, {"log foo" }, TestChannel::FOO}, |
32 | {{"bar" }, {"log bar" }, TestChannel::BAR}, |
33 | }; |
34 | |
35 | static Log::Channel test_channel(test_categories, TestChannel::FOO); |
36 | |
37 | namespace lldb_private { |
38 | template <> Log::Channel &LogChannelFor<TestChannel>() { return test_channel; } |
39 | } // namespace lldb_private |
40 | |
41 | // Wrap enable, disable and list functions to make them easier to test. |
42 | static bool EnableChannel(std::shared_ptr<LogHandler> log_handler_sp, |
43 | uint32_t log_options, llvm::StringRef channel, |
44 | llvm::ArrayRef<const char *> categories, |
45 | std::string &error) { |
46 | error.clear(); |
47 | llvm::raw_string_ostream error_stream(error); |
48 | return Log::EnableLogChannel(log_handler_sp, log_options, channel, categories, |
49 | error_stream); |
50 | } |
51 | |
52 | static bool DisableChannel(llvm::StringRef channel, |
53 | llvm::ArrayRef<const char *> categories, |
54 | std::string &error) { |
55 | error.clear(); |
56 | llvm::raw_string_ostream error_stream(error); |
57 | return Log::DisableLogChannel(channel, categories, error_stream); |
58 | } |
59 | |
60 | static bool ListCategories(llvm::StringRef channel, std::string &result) { |
61 | result.clear(); |
62 | llvm::raw_string_ostream result_stream(result); |
63 | return Log::ListChannelCategories(channel, stream&: result_stream); |
64 | } |
65 | |
66 | namespace { |
67 | // A test fixture which provides tests with a pre-registered channel. |
68 | struct LogChannelTest : public ::testing::Test { |
69 | void TearDown() override { Log::DisableAllLogChannels(); } |
70 | |
71 | static void SetUpTestCase() { Log::Register(name: "chan" , channel&: test_channel); } |
72 | |
73 | static void TearDownTestCase() { |
74 | Log::Unregister(name: "chan" ); |
75 | llvm::llvm_shutdown(); |
76 | } |
77 | }; |
78 | |
79 | class TestLogHandler : public LogHandler { |
80 | public: |
81 | TestLogHandler() : m_messages(), m_stream(m_messages) {} |
82 | |
83 | void Emit(llvm::StringRef message) override { m_stream << message; } |
84 | |
85 | llvm::SmallString<0> m_messages; |
86 | llvm::raw_svector_ostream m_stream; |
87 | }; |
88 | |
89 | // A test fixture which provides tests with a pre-registered and pre-enabled |
90 | // channel. Additionally, the messages written to that channel are captured and |
91 | // made available via getMessage(). |
92 | class LogChannelEnabledTest : public LogChannelTest { |
93 | std::shared_ptr<TestLogHandler> m_log_handler_sp = |
94 | std::make_shared<TestLogHandler>(); |
95 | Log *m_log; |
96 | size_t m_consumed_bytes = 0; |
97 | |
98 | protected: |
99 | std::shared_ptr<LogHandler> getLogHandler() { return m_log_handler_sp; } |
100 | Log *getLog() { return m_log; } |
101 | llvm::StringRef takeOutput(); |
102 | llvm::StringRef logAndTakeOutput(llvm::StringRef Message); |
103 | llvm::StringRef logAndTakeOutputf(llvm::StringRef Message); |
104 | |
105 | public: |
106 | void SetUp() override; |
107 | }; |
108 | |
109 | static std::string GetDumpAsString(const RotatingLogHandler &handler) { |
110 | std::string buffer; |
111 | llvm::raw_string_ostream stream(buffer); |
112 | handler.Dump(stream); |
113 | return buffer; |
114 | } |
115 | } // end anonymous namespace |
116 | |
117 | void LogChannelEnabledTest::SetUp() { |
118 | LogChannelTest::SetUp(); |
119 | |
120 | std::string error; |
121 | ASSERT_TRUE(EnableChannel(m_log_handler_sp, 0, "chan" , {}, error)); |
122 | |
123 | m_log = GetLog(mask: TestChannel::FOO); |
124 | ASSERT_NE(nullptr, m_log); |
125 | } |
126 | |
127 | llvm::StringRef LogChannelEnabledTest::takeOutput() { |
128 | llvm::StringRef result = |
129 | m_log_handler_sp->m_stream.str().drop_front(N: m_consumed_bytes); |
130 | m_consumed_bytes += result.size(); |
131 | return result; |
132 | } |
133 | |
134 | llvm::StringRef |
135 | LogChannelEnabledTest::logAndTakeOutput(llvm::StringRef Message) { |
136 | LLDB_LOG(m_log, "{0}" , Message); |
137 | return takeOutput(); |
138 | } |
139 | |
140 | llvm::StringRef |
141 | LogChannelEnabledTest::logAndTakeOutputf(llvm::StringRef Message) { |
142 | LLDB_LOGF(m_log, "%s" , Message.str().c_str()); |
143 | return takeOutput(); |
144 | } |
145 | |
146 | TEST(LogTest, LLDB_LOG_nullptr) { |
147 | Log *log = nullptr; |
148 | LLDB_LOG(log, "{0}" , 0); // Shouldn't crash |
149 | } |
150 | |
151 | TEST(LogTest, Register) { |
152 | llvm::llvm_shutdown_obj obj; |
153 | Log::Register(name: "chan" , channel&: test_channel); |
154 | Log::Unregister(name: "chan" ); |
155 | Log::Register(name: "chan" , channel&: test_channel); |
156 | Log::Unregister(name: "chan" ); |
157 | } |
158 | |
159 | TEST(LogTest, Unregister) { |
160 | llvm::llvm_shutdown_obj obj; |
161 | Log::Register(name: "chan" , channel&: test_channel); |
162 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
163 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
164 | EXPECT_TRUE( |
165 | Log::EnableLogChannel(log_handler_sp, 0, "chan" , {"foo" }, llvm::nulls())); |
166 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
167 | Log::Unregister(name: "chan" ); |
168 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
169 | } |
170 | |
171 | namespace { |
172 | static char test_baton; |
173 | static size_t callback_count = 0; |
174 | static void TestCallback(const char *data, void *baton) { |
175 | EXPECT_STREQ("Foobar" , data); |
176 | EXPECT_EQ(&test_baton, baton); |
177 | ++callback_count; |
178 | } |
179 | } // namespace |
180 | |
181 | TEST(LogTest, CallbackLogHandler) { |
182 | CallbackLogHandler handler(TestCallback, &test_baton); |
183 | handler.Emit(message: "Foobar" ); |
184 | EXPECT_EQ(1u, callback_count); |
185 | } |
186 | |
187 | TEST(LogHandlerTest, RotatingLogHandler) { |
188 | RotatingLogHandler handler(3); |
189 | |
190 | handler.Emit(message: "foo" ); |
191 | handler.Emit(message: "bar" ); |
192 | EXPECT_EQ(GetDumpAsString(handler), "foobar" ); |
193 | |
194 | handler.Emit(message: "baz" ); |
195 | handler.Emit(message: "qux" ); |
196 | EXPECT_EQ(GetDumpAsString(handler), "barbazqux" ); |
197 | |
198 | handler.Emit(message: "quux" ); |
199 | EXPECT_EQ(GetDumpAsString(handler), "bazquxquux" ); |
200 | } |
201 | |
202 | TEST(LogHandlerTest, TeeLogHandler) { |
203 | auto handler1 = std::make_shared<RotatingLogHandler>(args: 2); |
204 | auto handler2 = std::make_shared<RotatingLogHandler>(args: 2); |
205 | TeeLogHandler handler(handler1, handler2); |
206 | |
207 | handler.Emit(message: "foo" ); |
208 | handler.Emit(message: "bar" ); |
209 | |
210 | EXPECT_EQ(GetDumpAsString(*handler1), "foobar" ); |
211 | EXPECT_EQ(GetDumpAsString(*handler2), "foobar" ); |
212 | } |
213 | |
214 | TEST_F(LogChannelTest, Enable) { |
215 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
216 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
217 | std::string error; |
218 | ASSERT_FALSE(EnableChannel(log_handler_sp, 0, "chanchan" , {}, error)); |
219 | EXPECT_EQ("Invalid log channel 'chanchan'.\n" , error); |
220 | |
221 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {}, error)); |
222 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
223 | EXPECT_EQ(nullptr, GetLog(TestChannel::BAR)); |
224 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO | TestChannel::BAR)); |
225 | |
226 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {"bar" }, error)); |
227 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
228 | EXPECT_NE(nullptr, GetLog(TestChannel::BAR)); |
229 | |
230 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {"baz" }, error)); |
231 | EXPECT_NE(std::string::npos, error.find("unrecognized log category 'baz'" )) |
232 | << "error: " << error; |
233 | } |
234 | |
235 | TEST_F(LogChannelTest, EnableOptions) { |
236 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
237 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
238 | std::string error; |
239 | EXPECT_TRUE(EnableChannel(log_handler_sp, LLDB_LOG_OPTION_VERBOSE, "chan" , {}, |
240 | error)); |
241 | |
242 | Log *log = GetLog(mask: TestChannel::FOO); |
243 | ASSERT_NE(nullptr, log); |
244 | EXPECT_TRUE(log->GetVerbose()); |
245 | } |
246 | |
247 | TEST_F(LogChannelTest, Disable) { |
248 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
249 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
250 | std::string error; |
251 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {"foo" , "bar" }, error)); |
252 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
253 | EXPECT_NE(nullptr, GetLog(TestChannel::BAR)); |
254 | |
255 | EXPECT_TRUE(DisableChannel("chan" , {"bar" }, error)); |
256 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
257 | EXPECT_EQ(nullptr, GetLog(TestChannel::BAR)); |
258 | |
259 | EXPECT_TRUE(DisableChannel("chan" , {"baz" }, error)); |
260 | EXPECT_NE(std::string::npos, error.find("unrecognized log category 'baz'" )) |
261 | << "error: " << error; |
262 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
263 | EXPECT_EQ(nullptr, GetLog(TestChannel::BAR)); |
264 | |
265 | EXPECT_TRUE(DisableChannel("chan" , {}, error)); |
266 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO | TestChannel::BAR)); |
267 | } |
268 | |
269 | TEST_F(LogChannelTest, List) { |
270 | std::string list; |
271 | EXPECT_TRUE(ListCategories("chan" , list)); |
272 | std::string expected = |
273 | R"(Logging categories for 'chan': |
274 | all - all available logging categories |
275 | default - default set of logging categories |
276 | foo - log foo |
277 | bar - log bar |
278 | )" ; |
279 | EXPECT_EQ(expected, list); |
280 | |
281 | EXPECT_FALSE(ListCategories("chanchan" , list)); |
282 | EXPECT_EQ("Invalid log channel 'chanchan'.\n" , list); |
283 | } |
284 | |
285 | TEST_F(LogChannelEnabledTest, log_options) { |
286 | std::string Err; |
287 | EXPECT_EQ("Hello World\n" , logAndTakeOutput("Hello World" )); |
288 | EXPECT_TRUE(EnableChannel(getLogHandler(), 0, "chan" , {}, Err)); |
289 | EXPECT_EQ("Hello World\n" , logAndTakeOutput("Hello World" )); |
290 | |
291 | { |
292 | EXPECT_TRUE(EnableChannel(getLogHandler(), LLDB_LOG_OPTION_PREPEND_SEQUENCE, |
293 | "chan" , {}, Err)); |
294 | llvm::StringRef Msg = logAndTakeOutput(Message: "Hello World" ); |
295 | int seq_no; |
296 | EXPECT_EQ(1, sscanf(Msg.str().c_str(), "%d Hello World" , &seq_no)); |
297 | } |
298 | |
299 | { |
300 | EXPECT_TRUE(EnableChannel(getLogHandler(), |
301 | LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "chan" , {}, |
302 | Err)); |
303 | llvm::StringRef Msg = logAndTakeOutput(Message: "Hello World" ); |
304 | char File[12]; |
305 | char Function[17]; |
306 | |
307 | sscanf(s: Msg.str().c_str(), |
308 | format: "%[^:]:%s Hello World" , File, |
309 | Function); |
310 | EXPECT_STRCASEEQ("LogTest.cpp" , File); |
311 | EXPECT_STREQ("logAndTakeOutput" , Function); |
312 | } |
313 | |
314 | { |
315 | EXPECT_TRUE(EnableChannel(getLogHandler(), |
316 | LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "chan" , {}, |
317 | Err)); |
318 | llvm::StringRef Msg = logAndTakeOutputf(Message: "Hello World" ); |
319 | char File[12]; |
320 | char Function[18]; |
321 | |
322 | sscanf(s: Msg.str().c_str(), |
323 | format: "%[^:]:%s Hello World" , File, |
324 | Function); |
325 | EXPECT_STRCASEEQ("LogTest.cpp" , File); |
326 | EXPECT_STREQ("logAndTakeOutputf" , Function); |
327 | } |
328 | |
329 | EXPECT_TRUE(EnableChannel(getLogHandler(), |
330 | LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD, "chan" , {}, |
331 | Err)); |
332 | EXPECT_EQ(llvm::formatv("[{0,0+4}/{1,0+4}] Hello World\n" , ::getpid(), |
333 | llvm::get_threadid()) |
334 | .str(), |
335 | logAndTakeOutput("Hello World" )); |
336 | } |
337 | |
338 | TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) { |
339 | LLDB_LOG_ERROR(getLog(), llvm::Error::success(), "Foo failed: {0}" ); |
340 | ASSERT_EQ("" , takeOutput()); |
341 | |
342 | LLDB_LOG_ERROR(getLog(), |
343 | llvm::make_error<llvm::StringError>( |
344 | "My Error" , llvm::inconvertibleErrorCode()), |
345 | "Foo failed: {0}" ); |
346 | ASSERT_EQ("Foo failed: My Error\n" , takeOutput()); |
347 | |
348 | // Doesn't log, but doesn't assert either |
349 | LLDB_LOG_ERROR(nullptr, |
350 | llvm::make_error<llvm::StringError>( |
351 | "My Error" , llvm::inconvertibleErrorCode()), |
352 | "Foo failed: {0}" ); |
353 | } |
354 | |
355 | TEST_F(LogChannelEnabledTest, LogThread) { |
356 | // Test that we are able to concurrently write to a log channel and disable |
357 | // it. |
358 | std::string err; |
359 | |
360 | // Start logging on one thread. Concurrently, try disabling the log channel. |
361 | std::thread log_thread([this] { LLDB_LOG(getLog(), "Hello World" ); }); |
362 | EXPECT_TRUE(DisableChannel("chan" , {}, err)); |
363 | log_thread.join(); |
364 | |
365 | // The log thread either managed to write to the log in time, or it didn't. In |
366 | // either case, we should not trip any undefined behavior (run the test under |
367 | // TSAN to verify this). |
368 | EXPECT_THAT(takeOutput(), testing::AnyOf("" , "Hello World\n" )); |
369 | } |
370 | |
371 | TEST_F(LogChannelEnabledTest, LogVerboseThread) { |
372 | // Test that we are able to concurrently check the verbose flag of a log |
373 | // channel and enable it. |
374 | std::string err; |
375 | |
376 | // Start logging on one thread. Concurrently, try enabling the log channel |
377 | // (with different log options). |
378 | std::thread log_thread([this] { LLDB_LOGV(getLog(), "Hello World" ); }); |
379 | EXPECT_TRUE( |
380 | EnableChannel(getLogHandler(), LLDB_LOG_OPTION_VERBOSE, "chan" , {}, err)); |
381 | log_thread.join(); |
382 | |
383 | // The log thread either managed to write to the log, or it didn't. In either |
384 | // case, we should not trip any undefined behavior (run the test under TSAN to |
385 | // verify this). |
386 | EXPECT_THAT(takeOutput(), testing::AnyOf("" , "Hello World\n" )); |
387 | } |
388 | |
389 | TEST_F(LogChannelEnabledTest, LogGetLogThread) { |
390 | // Test that we are able to concurrently get mask of a Log object and disable |
391 | // it. |
392 | std::string err; |
393 | |
394 | // Try fetching the log mask on one thread. Concurrently, try disabling the |
395 | // log channel. |
396 | uint64_t mask; |
397 | std::thread log_thread([this, &mask] { mask = getLog()->GetMask(); }); |
398 | EXPECT_TRUE(DisableChannel("chan" , {}, err)); |
399 | log_thread.join(); |
400 | |
401 | // The mask should be either zero of "FOO". In either case, we should not trip |
402 | // any undefined behavior (run the test under TSAN to verify this). |
403 | EXPECT_THAT(mask, testing::AnyOf(0, Log::MaskType(TestChannel::FOO))); |
404 | } |
405 | |