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