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