Branch data Line data Source code
1 : : // Copyright (c) 2019-2022 The Bitcoin Core developers
2 : : // Distributed under the MIT software license, see the accompanying
3 : : // file COPYING or http://www.opensource.org/licenses/mit-license.php.
4 : :
5 : : #include <init/common.h>
6 : : #include <logging.h>
7 : : #include <logging/timer.h>
8 : : #include <scheduler.h>
9 : : #include <test/util/logging.h>
10 : : #include <test/util/setup_common.h>
11 : : #include <tinyformat.h>
12 : : #include <util/fs.h>
13 : : #include <util/fs_helpers.h>
14 : : #include <util/string.h>
15 : :
16 : : #include <chrono>
17 : : #include <fstream>
18 : : #include <future>
19 : : #include <ios>
20 : : #include <iostream>
21 : : #include <source_location>
22 : : #include <string>
23 : : #include <unordered_map>
24 : : #include <utility>
25 : : #include <vector>
26 : :
27 : : #include <boost/test/unit_test.hpp>
28 : :
29 : : using util::SplitString;
30 : : using util::TrimString;
31 : :
32 : : BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
33 : :
34 : 3 : static void ResetLogger()
35 : : {
36 : 3 : LogInstance().SetLogLevel(BCLog::DEFAULT_LOG_LEVEL);
37 [ + - ]: 3 : LogInstance().SetCategoryLogLevel({});
38 : 3 : }
39 : :
40 : : struct LogSetup : public BasicTestingSetup {
41 : : fs::path prev_log_path;
42 : : fs::path tmp_log_path;
43 : : bool prev_reopen_file;
44 : : bool prev_print_to_file;
45 : : bool prev_log_timestamps;
46 : : bool prev_log_threadnames;
47 : : bool prev_log_sourcelocations;
48 : : std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
49 : : BCLog::Level prev_log_level;
50 : :
51 [ + - ]: 7 : LogSetup() : prev_log_path{LogInstance().m_file_path},
52 [ + - + - ]: 14 : tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
53 [ + - + - ]: 7 : prev_reopen_file{LogInstance().m_reopen_file},
54 [ + - ]: 7 : prev_print_to_file{LogInstance().m_print_to_file},
55 [ + - ]: 7 : prev_log_timestamps{LogInstance().m_log_timestamps},
56 [ + - ]: 7 : prev_log_threadnames{LogInstance().m_log_threadnames},
57 [ + - ]: 7 : prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
58 [ + - + - ]: 7 : prev_category_levels{LogInstance().CategoryLevels()},
59 [ + - + - : 14 : prev_log_level{LogInstance().LogLevel()}
+ - ]
60 : : {
61 [ + - + - ]: 7 : LogInstance().m_file_path = tmp_log_path;
62 [ + - + - ]: 7 : LogInstance().m_reopen_file = true;
63 [ + - ]: 7 : LogInstance().m_print_to_file = true;
64 [ + - ]: 7 : LogInstance().m_log_timestamps = false;
65 [ + - ]: 7 : LogInstance().m_log_threadnames = false;
66 : :
67 : : // Prevent tests from failing when the line number of the logs changes.
68 [ + - ]: 7 : LogInstance().m_log_sourcelocations = false;
69 : :
70 [ + - + - ]: 7 : LogInstance().SetLogLevel(BCLog::Level::Debug);
71 [ + - + - ]: 7 : LogInstance().SetCategoryLogLevel({});
72 [ + - ]: 14 : }
73 : :
74 : 7 : ~LogSetup()
75 : : {
76 : 7 : LogInstance().m_file_path = prev_log_path;
77 : 7 : LogInfo("Sentinel log to reopen log file");
78 : 7 : LogInstance().m_print_to_file = prev_print_to_file;
79 : 7 : LogInstance().m_reopen_file = prev_reopen_file;
80 : 7 : LogInstance().m_log_timestamps = prev_log_timestamps;
81 : 7 : LogInstance().m_log_threadnames = prev_log_threadnames;
82 : 7 : LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
83 : 7 : LogInstance().SetLogLevel(prev_log_level);
84 : 7 : LogInstance().SetCategoryLogLevel(prev_category_levels);
85 : 21 : }
86 : : };
87 : :
88 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_timer)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
89 : : {
90 [ + - + - ]: 2 : auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
91 [ + - ]: 1 : const std::string_view result_prefix{"tests: msg ("};
92 [ + - + - : 1 : BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);
+ - + - +
- ]
93 : 1 : }
94 : :
95 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
96 : : {
97 : 1 : LogInstance().m_log_sourcelocations = true;
98 : :
99 : 12 : struct Case {
100 : : std::string msg;
101 : : BCLog::LogFlags category;
102 : : BCLog::Level level;
103 : : std::string prefix;
104 : : std::source_location loc;
105 : : };
106 : :
107 : 1 : std::vector<Case> cases = {
108 [ + - ]: 1 : {"foo1: bar1", BCLog::NET, BCLog::Level::Debug, "[net] ", std::source_location::current()},
109 : : {"foo2: bar2", BCLog::NET, BCLog::Level::Info, "[net:info] ", std::source_location::current()},
110 : : {"foo3: bar3", BCLog::ALL, BCLog::Level::Debug, "[debug] ", std::source_location::current()},
111 : : {"foo4: bar4", BCLog::ALL, BCLog::Level::Info, "", std::source_location::current()},
112 : : {"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ", std::source_location::current()},
113 : : {"foo6: bar6", BCLog::NONE, BCLog::Level::Info, "", std::source_location::current()},
114 [ - + + + : 7 : };
- - ]
115 : :
116 : 1 : std::vector<std::string> expected;
117 [ + + ]: 7 : for (auto& [msg, category, level, prefix, loc] : cases) {
118 [ + - + - : 30 : expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg));
+ - + - +
- ]
119 [ + - + - ]: 6 : LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false);
120 : : }
121 [ + - ]: 1 : std::ifstream file{tmp_log_path};
122 : 1 : std::vector<std::string> log_lines;
123 [ + - + + ]: 7 : for (std::string log; std::getline(file, log);) {
124 [ + - ]: 6 : log_lines.push_back(log);
125 : 0 : }
126 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
127 [ + - + - : 2 : }
+ - + - +
- + - + -
+ - + - +
- + - + -
- - ]
128 : :
129 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
130 : : {
131 : 1 : LogPrintf("foo5: %s\n", "bar5");
132 [ - + ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged
133 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7");
134 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8");
135 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9");
136 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10");
137 : 1 : std::ifstream file{tmp_log_path};
138 : 1 : std::vector<std::string> log_lines;
139 [ + - + + ]: 6 : for (std::string log; std::getline(file, log);) {
140 [ + - ]: 5 : log_lines.push_back(log);
141 : 0 : }
142 : 1 : std::vector<std::string> expected = {
143 : : "foo5: bar5",
144 : : "[net] foo7: bar7",
145 : : "[net:info] foo8: bar8",
146 : : "[net:warning] foo9: bar9",
147 : : "[net:error] foo10: bar10",
148 [ + - ]: 1 : };
149 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
150 : 1 : }
151 : :
152 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
153 : : {
154 [ - + ]: 1 : LogTrace(BCLog::NET, "foo6: %s", "bar6"); // not logged
155 [ + - ]: 1 : LogDebug(BCLog::NET, "foo7: %s", "bar7");
156 : 1 : LogInfo("foo8: %s", "bar8");
157 : 1 : LogWarning("foo9: %s", "bar9");
158 : 1 : LogError("foo10: %s", "bar10");
159 : 1 : std::ifstream file{tmp_log_path};
160 : 1 : std::vector<std::string> log_lines;
161 [ + - + + ]: 5 : for (std::string log; std::getline(file, log);) {
162 [ + - ]: 4 : log_lines.push_back(log);
163 : 0 : }
164 : 1 : std::vector<std::string> expected = {
165 : : "[net] foo7: bar7",
166 : : "foo8: bar8",
167 : : "[warning] foo9: bar9",
168 : : "[error] foo10: bar10",
169 [ + - ]: 1 : };
170 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
171 : 1 : }
172 : :
173 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
174 : : {
175 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::ALL);
176 : 1 : const auto concatenated_category_names = LogInstance().LogCategoriesString();
177 : 1 : std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
178 [ + - ]: 1 : const auto category_names = SplitString(concatenated_category_names, ',');
179 [ + + ]: 29 : for (const auto& category_name : category_names) {
180 : 28 : BCLog::LogFlags category;
181 [ + - ]: 28 : const auto trimmed_category_name = TrimString(category_name);
182 [ + - + - : 56 : BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name));
+ - + - ]
183 [ + - ]: 28 : expected_category_names.emplace_back(category, trimmed_category_name);
184 : 28 : }
185 : :
186 : 1 : std::vector<std::string> expected;
187 [ + - + + ]: 29 : for (const auto& [category, name] : expected_category_names) {
188 [ + - + - : 28 : LogDebug(category, "foo: %s\n", "bar");
+ - ]
189 [ + - ]: 28 : std::string expected_log = "[";
190 [ + - ]: 28 : expected_log += name;
191 [ + - ]: 28 : expected_log += "] foo: bar";
192 [ + - ]: 28 : expected.push_back(expected_log);
193 : 28 : }
194 : :
195 [ + - ]: 1 : std::ifstream file{tmp_log_path};
196 : 1 : std::vector<std::string> log_lines;
197 [ + - + + ]: 29 : for (std::string log; std::getline(file, log);) {
198 [ + - ]: 28 : log_lines.push_back(log);
199 : 0 : }
200 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
201 : 1 : }
202 : :
203 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
204 : : {
205 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::ALL);
206 : :
207 : 1 : LogInstance().SetLogLevel(BCLog::Level::Debug);
208 : 1 : LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
209 : :
210 : : // Global log level
211 [ + - ]: 1 : LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
212 [ - + ]: 1 : LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
213 [ + - ]: 1 : LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
214 [ + - ]: 1 : LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
215 : :
216 : : // Category-specific log level
217 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
218 [ - + ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo6: %s. This log level is the same as the global one but lower than the category-specific one, which takes precedence. \n", "bar6");
219 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
220 : :
221 : 1 : std::vector<std::string> expected = {
222 : : "[http:info] foo1: bar1",
223 : : "[validation:warning] foo3: bar3",
224 : : "[rpc:error] foo4: bar4",
225 : : "[net:warning] foo5: bar5",
226 : : "[net:error] foo7: bar7",
227 : 1 : };
228 [ + - ]: 1 : std::ifstream file{tmp_log_path};
229 : 1 : std::vector<std::string> log_lines;
230 [ + - + + ]: 6 : for (std::string log; std::getline(file, log);) {
231 [ + - ]: 5 : log_lines.push_back(log);
232 : 0 : }
233 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
234 : 1 : }
235 : :
236 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
237 : : {
238 : : // Set global log level
239 : 1 : {
240 : 1 : ResetLogger();
241 : 1 : ArgsManager args;
242 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
243 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
244 [ + - ]: 1 : std::string err;
245 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
+ - + - ]
246 : :
247 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
248 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
249 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
+ - ]
250 : 1 : }
251 : :
252 : : // Set category-specific log level
253 : 1 : {
254 : 1 : ResetLogger();
255 : 1 : ArgsManager args;
256 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
257 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
258 [ + - ]: 1 : std::string err;
259 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
+ - + - ]
260 : :
261 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
262 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
263 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL);
+ - ]
264 : :
265 [ + - + - ]: 1 : const auto& category_levels{LogInstance().CategoryLevels()};
266 : 1 : const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
267 [ + - + - : 3 : BOOST_REQUIRE(net_it != category_levels.end());
+ - + - ]
268 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
269 : 1 : }
270 : :
271 : : // Set both global log level and category-specific log level
272 : 1 : {
273 : 1 : ResetLogger();
274 : 1 : ArgsManager args;
275 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
276 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
277 [ + - ]: 1 : std::string err;
278 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(4, argv_test, err));
+ - + - ]
279 : :
280 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
281 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
282 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
+ - ]
283 : :
284 [ + - + - ]: 1 : const auto& category_levels{LogInstance().CategoryLevels()};
285 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(category_levels.size(), 2);
286 : :
287 : 1 : const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
288 [ + - + - : 3 : BOOST_CHECK(net_it != category_levels.end());
+ - + - ]
289 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
290 : :
291 : 1 : const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
292 [ + - + - : 3 : BOOST_CHECK(http_it != category_levels.end());
+ - + - ]
293 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
294 : 1 : }
295 : 1 : }
296 : :
297 : 2 : void MockForwardAndSync(CScheduler& scheduler, std::chrono::seconds duration)
298 : : {
299 : 2 : scheduler.MockForward(duration);
300 : 2 : std::promise<void> promise;
301 [ + - ]: 4 : scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms);
302 [ + - + - ]: 4 : promise.get_future().wait();
303 : 2 : }
304 : :
305 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
306 : : {
307 : 1 : CScheduler scheduler{};
308 [ + - ]: 2 : scheduler.m_service_thread = std::thread([&scheduler] { scheduler.serviceQueue(); });
309 : 1 : uint64_t max_bytes{1024};
310 : 1 : auto reset_window{1min};
311 [ + - ]: 3 : auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); };
312 [ + - ]: 1 : BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window};
313 : :
314 : 1 : using Status = BCLog::LogRateLimiter::Status;
315 : 1 : auto source_loc_1{std::source_location::current()};
316 : 1 : auto source_loc_2{std::source_location::current()};
317 : :
318 : : // A fresh limiter should not have any suppressions
319 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
320 : :
321 : : // Resetting an unused limiter is fine
322 [ + - ]: 1 : limiter.Reset();
323 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
324 : :
325 : : // No suppression should happen until more than max_bytes have been consumed
326 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes - 1, 'a')), Status::UNSUPPRESSED);
+ - + - ]
327 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::UNSUPPRESSED);
+ - + - ]
328 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
329 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::NEWLY_SUPPRESSED);
+ - + - ]
330 [ + - + - : 2 : BOOST_CHECK(limiter.SuppressionsActive());
+ - ]
331 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::STILL_SUPPRESSED);
+ - + - ]
332 [ + - + - : 2 : BOOST_CHECK(limiter.SuppressionsActive());
+ - ]
333 : :
334 : : // Location 2 should not be affected by location 1's suppression
335 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
+ - + - ]
336 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, "a"), Status::NEWLY_SUPPRESSED);
+ - + - ]
337 [ + - + - ]: 2 : BOOST_CHECK(limiter.SuppressionsActive());
338 : :
339 : : // After reset_window time has passed, all suppressions should be cleared.
340 [ + - ]: 1 : MockForwardAndSync(scheduler, reset_window);
341 : :
342 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
343 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
+ - + - ]
344 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
+ - + - ]
345 : :
346 [ + - ]: 1 : scheduler.stop();
347 : 1 : }
348 : :
349 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
350 : : {
351 : 1 : BCLog::LogLimitStats counter{BCLog::RATELIMIT_MAX_BYTES};
352 : :
353 : : // Check that counter gets initialized correctly.
354 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES);
355 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull);
356 : :
357 : 1 : const uint64_t MESSAGE_SIZE{512 * 1024};
358 [ + - + - ]: 2 : BOOST_CHECK(counter.Consume(MESSAGE_SIZE));
359 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE);
360 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull);
361 : :
362 [ + - + - ]: 2 : BOOST_CHECK(counter.Consume(MESSAGE_SIZE));
363 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2);
364 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 0ull);
365 : :
366 : : // Consuming more bytes after already having consumed 1MB should fail.
367 [ + - + - ]: 2 : BOOST_CHECK(!counter.Consume(500));
368 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetAvailableBytes(), 0ull);
369 [ + - ]: 1 : BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull);
370 : 1 : }
371 : :
372 : 4099 : void LogFromLocation(int location, std::string message)
373 : : {
374 [ + + + + : 4099 : switch (location) {
- ]
375 : 2049 : case 0:
376 : 2049 : LogInfo("%s\n", message);
377 : 2049 : break;
378 : 2 : case 1:
379 : 2 : LogInfo("%s\n", message);
380 : 2 : break;
381 : 1024 : case 2:
382 [ + - ]: 1024 : LogPrintLevel(BCLog::LogFlags::NONE, BCLog::Level::Info, "%s\n", message);
383 : : break;
384 : 1024 : case 3:
385 [ + - ]: 1024 : LogPrintLevel(BCLog::LogFlags::ALL, BCLog::Level::Info, "%s\n", message);
386 : : break;
387 : : }
388 : 4099 : }
389 : :
390 : 2051 : void LogFromLocationAndExpect(int location, std::string message, std::string expect)
391 : : {
392 [ + - + - ]: 4102 : ASSERT_DEBUG_LOG(expect);
393 [ + - + - ]: 2051 : LogFromLocation(location, message);
394 : 2051 : }
395 : :
396 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
397 : : {
398 : 1 : bool prev_log_timestamps = LogInstance().m_log_timestamps;
399 : 1 : LogInstance().m_log_timestamps = false;
400 : 1 : bool prev_log_sourcelocations = LogInstance().m_log_sourcelocations;
401 : 1 : LogInstance().m_log_sourcelocations = false;
402 : 1 : bool prev_log_threadnames = LogInstance().m_log_threadnames;
403 : 1 : LogInstance().m_log_threadnames = false;
404 : :
405 : 1 : CScheduler scheduler{};
406 [ + - ]: 2 : scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); });
407 [ + - ]: 3 : auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); };
408 [ + - ]: 1 : auto limiter = std::make_unique<BCLog::LogRateLimiter>(sched_func, 1024 * 1024, 20s);
409 [ + - + - ]: 1 : LogInstance().SetRateLimiting(std::move(limiter));
410 : :
411 : : // Log 1024-character lines (1023 plus newline) to make the math simple.
412 [ + - + - ]: 1 : std::string log_message(1023, 'a');
413 : :
414 [ + - + - ]: 1 : std::string utf8_path{LogInstance().m_file_path.utf8string()};
415 [ + - ]: 1 : const char* log_path{utf8_path.c_str()};
416 : :
417 : : // Use GetFileSize because fs::file_size may require a flush to be accurate.
418 [ + - ]: 1 : std::streamsize log_file_size{static_cast<std::streamsize>(GetFileSize(log_path))};
419 : :
420 : : // Logging 1 MiB should be allowed.
421 [ + + ]: 1025 : for (int i = 0; i < 1024; ++i) {
422 [ + - + - ]: 2048 : LogFromLocation(0, log_message);
423 : : }
424 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "should be able to log 1 MiB from location 0");
+ - + - ]
425 : :
426 [ + - ]: 1 : log_file_size = GetFileSize(log_path);
427 : :
428 [ + - + - : 3 : BOOST_CHECK_NO_THROW(LogFromLocationAndExpect(0, log_message, "Excessive logging detected"));
+ - + - +
- - - - -
- - ]
429 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the start of the suppression period should be logged");
+ - + - ]
430 : :
431 [ + - ]: 1 : log_file_size = GetFileSize(log_path);
432 [ + + ]: 1025 : for (int i = 0; i < 1024; ++i) {
433 [ + - + - ]: 2048 : LogFromLocation(0, log_message);
434 : : }
435 : :
436 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size == GetFileSize(log_path), "all further logs from location 0 should be dropped");
+ - + - ]
437 : :
438 [ + - + - : 4 : BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Excessive logging detected"), std::runtime_error);
+ - - + -
- - - - +
+ - + - ]
439 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 1 should be unaffected by other locations");
+ - + - ]
440 : :
441 [ + - ]: 1 : log_file_size = GetFileSize(log_path);
442 : 1 : {
443 [ + - + - ]: 2 : ASSERT_DEBUG_LOG("Restarting logging");
444 [ + - ]: 1 : MockForwardAndSync(scheduler, 1min);
445 [ + - ]: 1 : }
446 : :
447 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the end of the suppression period should be logged");
+ - + - ]
448 : :
449 [ + - + - : 4 : BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error);
+ - - + -
- - - - +
+ - + - ]
450 : :
451 : : // Attempt to log 1MiB from location 2 and 1MiB from location 3. These exempt locations should be allowed to log
452 : : // without limit.
453 [ + - ]: 1 : log_file_size = GetFileSize(log_path);
454 [ + + ]: 1025 : for (int i = 0; i < 1024; ++i) {
455 [ + - + - : 4096 : BOOST_CHECK_THROW(LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error);
+ - - + -
- - - - +
+ - + - ]
456 : : }
457 : :
458 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 2 should be exempt from rate limiting");
+ - + - ]
459 : :
460 [ + - ]: 1 : log_file_size = GetFileSize(log_path);
461 [ + + ]: 1025 : for (int i = 0; i < 1024; ++i) {
462 [ + - + - : 4096 : BOOST_CHECK_THROW(LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error);
+ - - + -
- - - - +
+ - + - ]
463 : : }
464 : :
465 [ + - + - : 2 : BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting");
+ - + - ]
466 : :
467 [ + - ]: 1 : LogInstance().m_log_timestamps = prev_log_timestamps;
468 [ + - ]: 1 : LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
469 [ + - ]: 1 : LogInstance().m_log_threadnames = prev_log_threadnames;
470 [ + - ]: 1 : scheduler.stop();
471 [ + - + - ]: 1 : LogInstance().SetRateLimiting(nullptr);
472 : 1 : }
473 : :
474 : : BOOST_AUTO_TEST_SUITE_END()
|
