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 <test/util/setup_common.h>
9 : : #include <util/string.h>
10 : :
11 : : #include <chrono>
12 : : #include <fstream>
13 : : #include <iostream>
14 : : #include <unordered_map>
15 : : #include <utility>
16 : : #include <vector>
17 : :
18 : : #include <boost/test/unit_test.hpp>
19 : :
20 : : using util::SplitString;
21 : : using util::TrimString;
22 : :
23 : : BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
24 : :
25 : 3 : static void ResetLogger()
26 : : {
27 : 3 : LogInstance().SetLogLevel(BCLog::DEFAULT_LOG_LEVEL);
28 [ + - ]: 3 : LogInstance().SetCategoryLogLevel({});
29 : 3 : }
30 : :
31 : : struct LogSetup : public BasicTestingSetup {
32 : : fs::path prev_log_path;
33 : : fs::path tmp_log_path;
34 : : bool prev_reopen_file;
35 : : bool prev_print_to_file;
36 : : bool prev_log_timestamps;
37 : : bool prev_log_threadnames;
38 : : bool prev_log_sourcelocations;
39 : : std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
40 : : BCLog::Level prev_log_level;
41 : :
42 [ + - + - ]: 6 : LogSetup() : prev_log_path{LogInstance().m_file_path},
43 [ + - + - ]: 12 : tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
44 [ + - + - ]: 6 : prev_reopen_file{LogInstance().m_reopen_file},
45 [ + - ]: 6 : prev_print_to_file{LogInstance().m_print_to_file},
46 [ + - ]: 6 : prev_log_timestamps{LogInstance().m_log_timestamps},
47 [ + - ]: 6 : prev_log_threadnames{LogInstance().m_log_threadnames},
48 [ + - ]: 6 : prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
49 [ + - + - ]: 6 : prev_category_levels{LogInstance().CategoryLevels()},
50 [ + - + - : 12 : prev_log_level{LogInstance().LogLevel()}
+ - ]
51 : : {
52 [ + - + - ]: 6 : LogInstance().m_file_path = tmp_log_path;
53 [ + - + - ]: 6 : LogInstance().m_reopen_file = true;
54 [ + - ]: 6 : LogInstance().m_print_to_file = true;
55 [ + - ]: 6 : LogInstance().m_log_timestamps = false;
56 [ + - ]: 6 : LogInstance().m_log_threadnames = false;
57 : :
58 : : // Prevent tests from failing when the line number of the logs changes.
59 [ + - ]: 6 : LogInstance().m_log_sourcelocations = false;
60 : :
61 [ + - + - ]: 6 : LogInstance().SetLogLevel(BCLog::Level::Debug);
62 [ + - + - ]: 6 : LogInstance().SetCategoryLogLevel({});
63 : 6 : }
64 : :
65 : 6 : ~LogSetup()
66 : : {
67 : 6 : LogInstance().m_file_path = prev_log_path;
68 : 6 : LogPrintf("Sentinel log to reopen log file\n");
69 : 6 : LogInstance().m_print_to_file = prev_print_to_file;
70 : 6 : LogInstance().m_reopen_file = prev_reopen_file;
71 : 6 : LogInstance().m_log_timestamps = prev_log_timestamps;
72 : 6 : LogInstance().m_log_threadnames = prev_log_threadnames;
73 : 6 : LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
74 : 6 : LogInstance().SetLogLevel(prev_log_level);
75 : 6 : LogInstance().SetCategoryLogLevel(prev_category_levels);
76 : 18 : }
77 : : };
78 : :
79 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_timer)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
80 : : {
81 [ + - + - ]: 2 : auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
82 [ + - ]: 1 : const std::string_view result_prefix{"tests: msg ("};
83 [ + - + - : 2 : BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);
+ - + - ]
84 : 1 : }
85 : :
86 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
87 : : {
88 : 1 : LogInstance().m_log_sourcelocations = true;
89 [ + - + - ]: 2 : LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s\n", "bar1");
90 [ + - + - ]: 2 : LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info, "foo2: %s\n", "bar2");
91 [ + - + - ]: 2 : LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug, "foo3: %s\n", "bar3");
92 [ + - + - ]: 2 : LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info, "foo4: %s\n", "bar4");
93 [ + - + - ]: 2 : LogPrintf_("fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo5: %s\n", "bar5");
94 [ + - + - ]: 2 : LogPrintf_("fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo6: %s\n", "bar6");
95 : 1 : std::ifstream file{tmp_log_path};
96 : 1 : std::vector<std::string> log_lines;
97 [ + - + + ]: 7 : for (std::string log; std::getline(file, log);) {
98 [ + - ]: 6 : log_lines.push_back(log);
99 : 0 : }
100 : 1 : std::vector<std::string> expected = {
101 : : "[src1:1] [fn1] [net] foo1: bar1",
102 : : "[src2:2] [fn2] [net:info] foo2: bar2",
103 : : "[src3:3] [fn3] [debug] foo3: bar3",
104 : : "[src4:4] [fn4] foo4: bar4",
105 : : "[src5:5] [fn5] [debug] foo5: bar5",
106 : : "[src6:6] [fn6] foo6: bar6",
107 [ + - ]: 1 : };
108 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
109 : 1 : }
110 : :
111 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
112 : : {
113 [ + - + - ]: 2 : LogPrintf("foo5: %s\n", "bar5");
114 [ + - + - : 2 : LogPrint(BCLog::NET, "foo6: %s\n", "bar6");
+ - ]
115 [ - + - - : 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged
- - ]
116 [ + - + - : 2 : LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7");
+ - ]
117 [ + - + - : 2 : LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8");
+ - ]
118 [ + - + - : 2 : LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9");
+ - ]
119 [ + - + - : 2 : LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10");
+ - ]
120 [ + - + - ]: 2 : LogPrintfCategory(BCLog::VALIDATION, "foo11: %s\n", "bar11");
121 : 1 : std::ifstream file{tmp_log_path};
122 : 1 : std::vector<std::string> log_lines;
123 [ + - + + ]: 8 : for (std::string log; std::getline(file, log);) {
124 [ + - ]: 7 : log_lines.push_back(log);
125 : 0 : }
126 : 1 : std::vector<std::string> expected = {
127 : : "foo5: bar5",
128 : : "[net] foo6: bar6",
129 : : "[net] foo7: bar7",
130 : : "[net:info] foo8: bar8",
131 : : "[net:warning] foo9: bar9",
132 : : "[net:error] foo10: bar10",
133 : : "[validation:info] foo11: bar11",
134 [ + - ]: 1 : };
135 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
136 : 1 : }
137 : :
138 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
139 : : {
140 [ - + - - : 1 : LogTrace(BCLog::NET, "foo6: %s\n", "bar6"); // not logged
- - ]
141 [ + - + - : 2 : LogDebug(BCLog::NET, "foo7: %s\n", "bar7");
+ - ]
142 [ + - + - ]: 2 : LogInfo("foo8: %s\n", "bar8");
143 [ + - + - ]: 2 : LogWarning("foo9: %s\n", "bar9");
144 [ + - + - ]: 2 : LogError("foo10: %s\n", "bar10");
145 : 1 : std::ifstream file{tmp_log_path};
146 : 1 : std::vector<std::string> log_lines;
147 [ + - + + ]: 5 : for (std::string log; std::getline(file, log);) {
148 [ + - ]: 4 : log_lines.push_back(log);
149 : 0 : }
150 : 1 : std::vector<std::string> expected = {
151 : : "[net] foo7: bar7",
152 : : "foo8: bar8",
153 : : "[warning] foo9: bar9",
154 : : "[error] foo10: bar10",
155 [ + - ]: 1 : };
156 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
157 : 1 : }
158 : :
159 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
160 : : {
161 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::ALL);
162 : 1 : const auto concatenated_category_names = LogInstance().LogCategoriesString();
163 : 1 : std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
164 [ + - ]: 1 : const auto category_names = SplitString(concatenated_category_names, ',');
165 [ + + ]: 29 : for (const auto& category_name : category_names) {
166 : 28 : BCLog::LogFlags category;
167 [ + - ]: 28 : const auto trimmed_category_name = TrimString(category_name);
168 [ + - + - : 56 : BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name));
+ - + - ]
169 [ + - ]: 28 : expected_category_names.emplace_back(category, trimmed_category_name);
170 : 28 : }
171 : :
172 : 1 : std::vector<std::string> expected;
173 [ + - + + ]: 29 : for (const auto& [category, name] : expected_category_names) {
174 [ + - + - : 56 : LogPrint(category, "foo: %s\n", "bar");
+ - + - +
- ]
175 [ + - ]: 28 : std::string expected_log = "[";
176 [ + - ]: 28 : expected_log += name;
177 [ + - ]: 28 : expected_log += "] foo: bar";
178 [ + - ]: 28 : expected.push_back(expected_log);
179 : 28 : }
180 : :
181 [ + - ]: 1 : std::ifstream file{tmp_log_path};
182 : 1 : std::vector<std::string> log_lines;
183 [ + - + + ]: 29 : for (std::string log; std::getline(file, log);) {
184 [ + - ]: 28 : log_lines.push_back(log);
185 : 0 : }
186 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
187 : 1 : }
188 : :
189 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
190 : : {
191 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::ALL);
192 : :
193 : 1 : LogInstance().SetLogLevel(BCLog::Level::Debug);
194 [ + - + - ]: 2 : LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
195 : :
196 : : // Global log level
197 [ + - + - : 2 : LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
+ - ]
198 [ - + - - : 1 : LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
- - ]
199 [ + - + - : 2 : LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
+ - ]
200 [ + - + - : 2 : LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
+ - ]
201 : :
202 : : // Category-specific log level
203 [ + - + - : 2 : LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
+ - ]
204 [ - + - - : 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");
- - ]
205 [ + - + - : 2 : LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
+ - ]
206 : :
207 : 1 : std::vector<std::string> expected = {
208 : : "[http:info] foo1: bar1",
209 : : "[validation:warning] foo3: bar3",
210 : : "[rpc:error] foo4: bar4",
211 : : "[net:warning] foo5: bar5",
212 : : "[net:error] foo7: bar7",
213 : 1 : };
214 [ + - ]: 1 : std::ifstream file{tmp_log_path};
215 : 1 : std::vector<std::string> log_lines;
216 [ + - + + ]: 6 : for (std::string log; std::getline(file, log);) {
217 [ + - ]: 5 : log_lines.push_back(log);
218 : 0 : }
219 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
220 : 1 : }
221 : :
222 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- + - + -
+ - + - +
- ]
223 : : {
224 : : // Set global log level
225 : 1 : {
226 : 1 : ResetLogger();
227 : 1 : ArgsManager args;
228 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
229 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
230 [ + - ]: 1 : std::string err;
231 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
+ - + - ]
232 : :
233 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
234 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
235 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
+ - ]
236 : 1 : }
237 : :
238 : : // Set category-specific 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=net:trace"};
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::DEFAULT_LOG_LEVEL);
+ - ]
250 : :
251 [ + - + - ]: 1 : const auto& category_levels{LogInstance().CategoryLevels()};
252 : 1 : const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
253 [ + - + - : 2 : BOOST_REQUIRE(net_it != category_levels.end());
+ - ]
254 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
255 : 1 : }
256 : :
257 : : // Set both global log level and category-specific log level
258 : 1 : {
259 : 1 : ResetLogger();
260 : 1 : ArgsManager args;
261 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
262 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
263 [ + - ]: 1 : std::string err;
264 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(4, argv_test, err));
+ - + - ]
265 : :
266 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
267 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
268 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
+ - ]
269 : :
270 [ + - + - ]: 1 : const auto& category_levels{LogInstance().CategoryLevels()};
271 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(category_levels.size(), 2);
272 : :
273 : 1 : const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
274 [ + - + - : 2 : BOOST_CHECK(net_it != category_levels.end());
+ - ]
275 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
276 : :
277 : 1 : const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
278 [ + - + - : 2 : BOOST_CHECK(http_it != category_levels.end());
+ - ]
279 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
280 : 1 : }
281 : 1 : }
282 : :
283 : : BOOST_AUTO_TEST_SUITE_END()
|
