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 | std::string message; |
164 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
165 | EXPECT_TRUE( |
166 | Log::EnableLogChannel(log_handler_sp, 0, "chan" , {"foo" }, llvm::nulls())); |
167 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
168 | Log::Unregister(name: "chan" ); |
169 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
170 | } |
171 | |
172 | namespace { |
173 | static char test_baton; |
174 | static size_t callback_count = 0; |
175 | static void TestCallback(const char *data, void *baton) { |
176 | EXPECT_STREQ("Foobar" , data); |
177 | EXPECT_EQ(&test_baton, baton); |
178 | ++callback_count; |
179 | } |
180 | } // namespace |
181 | |
182 | TEST(LogTest, CallbackLogHandler) { |
183 | CallbackLogHandler handler(TestCallback, &test_baton); |
184 | handler.Emit(message: "Foobar" ); |
185 | EXPECT_EQ(1u, callback_count); |
186 | } |
187 | |
188 | TEST(LogHandlerTest, RotatingLogHandler) { |
189 | RotatingLogHandler handler(3); |
190 | |
191 | handler.Emit(message: "foo" ); |
192 | handler.Emit(message: "bar" ); |
193 | EXPECT_EQ(GetDumpAsString(handler), "foobar" ); |
194 | |
195 | handler.Emit(message: "baz" ); |
196 | handler.Emit(message: "qux" ); |
197 | EXPECT_EQ(GetDumpAsString(handler), "barbazqux" ); |
198 | |
199 | handler.Emit(message: "quux" ); |
200 | EXPECT_EQ(GetDumpAsString(handler), "bazquxquux" ); |
201 | } |
202 | |
203 | TEST_F(LogChannelTest, Enable) { |
204 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
205 | std::string message; |
206 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
207 | std::string error; |
208 | ASSERT_FALSE(EnableChannel(log_handler_sp, 0, "chanchan" , {}, error)); |
209 | EXPECT_EQ("Invalid log channel 'chanchan'.\n" , error); |
210 | |
211 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {}, error)); |
212 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
213 | EXPECT_EQ(nullptr, GetLog(TestChannel::BAR)); |
214 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO | TestChannel::BAR)); |
215 | |
216 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {"bar" }, error)); |
217 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
218 | EXPECT_NE(nullptr, GetLog(TestChannel::BAR)); |
219 | |
220 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {"baz" }, error)); |
221 | EXPECT_NE(std::string::npos, error.find("unrecognized log category 'baz'" )) |
222 | << "error: " << error; |
223 | } |
224 | |
225 | TEST_F(LogChannelTest, EnableOptions) { |
226 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
227 | std::string message; |
228 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
229 | std::string error; |
230 | EXPECT_TRUE(EnableChannel(log_handler_sp, LLDB_LOG_OPTION_VERBOSE, "chan" , {}, |
231 | error)); |
232 | |
233 | Log *log = GetLog(mask: TestChannel::FOO); |
234 | ASSERT_NE(nullptr, log); |
235 | EXPECT_TRUE(log->GetVerbose()); |
236 | } |
237 | |
238 | TEST_F(LogChannelTest, Disable) { |
239 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO)); |
240 | std::string message; |
241 | auto log_handler_sp = std::make_shared<TestLogHandler>(); |
242 | std::string error; |
243 | EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan" , {"foo" , "bar" }, error)); |
244 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
245 | EXPECT_NE(nullptr, GetLog(TestChannel::BAR)); |
246 | |
247 | EXPECT_TRUE(DisableChannel("chan" , {"bar" }, error)); |
248 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
249 | EXPECT_EQ(nullptr, GetLog(TestChannel::BAR)); |
250 | |
251 | EXPECT_TRUE(DisableChannel("chan" , {"baz" }, error)); |
252 | EXPECT_NE(std::string::npos, error.find("unrecognized log category 'baz'" )) |
253 | << "error: " << error; |
254 | EXPECT_NE(nullptr, GetLog(TestChannel::FOO)); |
255 | EXPECT_EQ(nullptr, GetLog(TestChannel::BAR)); |
256 | |
257 | EXPECT_TRUE(DisableChannel("chan" , {}, error)); |
258 | EXPECT_EQ(nullptr, GetLog(TestChannel::FOO | TestChannel::BAR)); |
259 | } |
260 | |
261 | TEST_F(LogChannelTest, List) { |
262 | std::string list; |
263 | EXPECT_TRUE(ListCategories("chan" , list)); |
264 | std::string expected = |
265 | R"(Logging categories for 'chan': |
266 | all - all available logging categories |
267 | default - default set of logging categories |
268 | foo - log foo |
269 | bar - log bar |
270 | )" ; |
271 | EXPECT_EQ(expected, list); |
272 | |
273 | EXPECT_FALSE(ListCategories("chanchan" , list)); |
274 | EXPECT_EQ("Invalid log channel 'chanchan'.\n" , list); |
275 | } |
276 | |
277 | TEST_F(LogChannelEnabledTest, log_options) { |
278 | std::string Err; |
279 | EXPECT_EQ("Hello World\n" , logAndTakeOutput("Hello World" )); |
280 | EXPECT_TRUE(EnableChannel(getLogHandler(), 0, "chan" , {}, Err)); |
281 | EXPECT_EQ("Hello World\n" , logAndTakeOutput("Hello World" )); |
282 | |
283 | { |
284 | EXPECT_TRUE(EnableChannel(getLogHandler(), LLDB_LOG_OPTION_PREPEND_SEQUENCE, |
285 | "chan" , {}, Err)); |
286 | llvm::StringRef Msg = logAndTakeOutput(Message: "Hello World" ); |
287 | int seq_no; |
288 | EXPECT_EQ(1, sscanf(Msg.str().c_str(), "%d Hello World" , &seq_no)); |
289 | } |
290 | |
291 | { |
292 | EXPECT_TRUE(EnableChannel(getLogHandler(), |
293 | LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "chan" , {}, |
294 | Err)); |
295 | llvm::StringRef Msg = logAndTakeOutput(Message: "Hello World" ); |
296 | char File[12]; |
297 | char Function[17]; |
298 | |
299 | sscanf(s: Msg.str().c_str(), |
300 | format: "%[^:]:%s Hello World" , File, |
301 | Function); |
302 | EXPECT_STRCASEEQ("LogTest.cpp" , File); |
303 | EXPECT_STREQ("logAndTakeOutput" , Function); |
304 | } |
305 | |
306 | { |
307 | EXPECT_TRUE(EnableChannel(getLogHandler(), |
308 | LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "chan" , {}, |
309 | Err)); |
310 | llvm::StringRef Msg = logAndTakeOutputf(Message: "Hello World" ); |
311 | char File[12]; |
312 | char Function[18]; |
313 | |
314 | sscanf(s: Msg.str().c_str(), |
315 | format: "%[^:]:%s Hello World" , File, |
316 | Function); |
317 | EXPECT_STRCASEEQ("LogTest.cpp" , File); |
318 | EXPECT_STREQ("logAndTakeOutputf" , Function); |
319 | } |
320 | |
321 | EXPECT_TRUE(EnableChannel(getLogHandler(), |
322 | LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD, "chan" , {}, |
323 | Err)); |
324 | EXPECT_EQ(llvm::formatv("[{0,0+4}/{1,0+4}] Hello World\n" , ::getpid(), |
325 | llvm::get_threadid()) |
326 | .str(), |
327 | logAndTakeOutput("Hello World" )); |
328 | } |
329 | |
330 | TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) { |
331 | LLDB_LOG_ERROR(getLog(), llvm::Error::success(), "Foo failed: {0}" ); |
332 | ASSERT_EQ("" , takeOutput()); |
333 | |
334 | LLDB_LOG_ERROR(getLog(), |
335 | llvm::make_error<llvm::StringError>( |
336 | "My Error" , llvm::inconvertibleErrorCode()), |
337 | "Foo failed: {0}" ); |
338 | ASSERT_EQ("Foo failed: My Error\n" , takeOutput()); |
339 | |
340 | // Doesn't log, but doesn't assert either |
341 | LLDB_LOG_ERROR(nullptr, |
342 | llvm::make_error<llvm::StringError>( |
343 | "My Error" , llvm::inconvertibleErrorCode()), |
344 | "Foo failed: {0}" ); |
345 | } |
346 | |
347 | TEST_F(LogChannelEnabledTest, LogThread) { |
348 | // Test that we are able to concurrently write to a log channel and disable |
349 | // it. |
350 | std::string err; |
351 | |
352 | // Start logging on one thread. Concurrently, try disabling the log channel. |
353 | std::thread log_thread([this] { LLDB_LOG(getLog(), "Hello World" ); }); |
354 | EXPECT_TRUE(DisableChannel("chan" , {}, err)); |
355 | log_thread.join(); |
356 | |
357 | // The log thread either managed to write to the log in time, or it didn't. In |
358 | // either case, we should not trip any undefined behavior (run the test under |
359 | // TSAN to verify this). |
360 | EXPECT_THAT(takeOutput(), testing::AnyOf("" , "Hello World\n" )); |
361 | } |
362 | |
363 | TEST_F(LogChannelEnabledTest, LogVerboseThread) { |
364 | // Test that we are able to concurrently check the verbose flag of a log |
365 | // channel and enable it. |
366 | std::string err; |
367 | |
368 | // Start logging on one thread. Concurrently, try enabling the log channel |
369 | // (with different log options). |
370 | std::thread log_thread([this] { LLDB_LOGV(getLog(), "Hello World" ); }); |
371 | EXPECT_TRUE( |
372 | EnableChannel(getLogHandler(), LLDB_LOG_OPTION_VERBOSE, "chan" , {}, err)); |
373 | log_thread.join(); |
374 | |
375 | // The log thread either managed to write to the log, or it didn't. In either |
376 | // case, we should not trip any undefined behavior (run the test under TSAN to |
377 | // verify this). |
378 | EXPECT_THAT(takeOutput(), testing::AnyOf("" , "Hello World\n" )); |
379 | } |
380 | |
381 | TEST_F(LogChannelEnabledTest, LogGetLogThread) { |
382 | // Test that we are able to concurrently get mask of a Log object and disable |
383 | // it. |
384 | std::string err; |
385 | |
386 | // Try fetching the log mask on one thread. Concurrently, try disabling the |
387 | // log channel. |
388 | uint64_t mask; |
389 | std::thread log_thread([this, &mask] { mask = getLog()->GetMask(); }); |
390 | EXPECT_TRUE(DisableChannel("chan" , {}, err)); |
391 | log_thread.join(); |
392 | |
393 | // The mask should be either zero of "FOO". In either case, we should not trip |
394 | // any undefined behavior (run the test under TSAN to verify this). |
395 | EXPECT_THAT(mask, testing::AnyOf(0, Log::MaskType(TestChannel::FOO))); |
396 | } |
397 | |