Bitcoin Core  24.99.0
P2P Digital Currency
logging_tests.cpp
Go to the documentation of this file.
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>
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 BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
21 
22 static void ResetLogger()
23 {
26 }
27 
28 struct LogSetup : public BasicTestingSetup {
36  std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
38 
39  LogSetup() : prev_log_path{LogInstance().m_file_path},
40  tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
41  prev_reopen_file{LogInstance().m_reopen_file},
42  prev_print_to_file{LogInstance().m_print_to_file},
43  prev_log_timestamps{LogInstance().m_log_timestamps},
44  prev_log_threadnames{LogInstance().m_log_threadnames},
45  prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
46  prev_category_levels{LogInstance().CategoryLevels()},
47  prev_log_level{LogInstance().LogLevel()}
48  {
50  LogInstance().m_reopen_file = true;
52  LogInstance().m_log_timestamps = false;
54 
55  // Prevent tests from failing when the line number of the logs changes.
57 
60  }
61 
63  {
65  LogPrintf("Sentinel log to reopen log file\n");
73  }
74 };
75 
76 BOOST_AUTO_TEST_CASE(logging_timer)
77 {
78  SetMockTime(1);
79  auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
80  SetMockTime(2);
81  BOOST_CHECK_EQUAL(micro_timer.LogMsg("test micros"), "tests: test micros (1000000μs)");
82 
83  SetMockTime(1);
84  auto ms_timer = BCLog::Timer<std::chrono::milliseconds>("tests", "end_msg");
85  SetMockTime(2);
86  BOOST_CHECK_EQUAL(ms_timer.LogMsg("test ms"), "tests: test ms (1000.00ms)");
87 
88  SetMockTime(1);
89  auto sec_timer = BCLog::Timer<std::chrono::seconds>("tests", "end_msg");
90  SetMockTime(2);
91  BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)");
92 }
93 
94 BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
95 {
97  LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s", "bar1\n");
98  LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s", "bar2\n");
99  LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s", "bar3\n");
100  LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s", "bar4\n");
101  std::ifstream file{tmp_log_path};
102  std::vector<std::string> log_lines;
103  for (std::string log; std::getline(file, log);) {
104  log_lines.push_back(log);
105  }
106  std::vector<std::string> expected = {
107  "[src1:1] [fn1] [net:debug] foo1: bar1",
108  "[src2:2] [fn2] [net] foo2: bar2",
109  "[src3:3] [fn3] [debug] foo3: bar3",
110  "[src4:4] [fn4] foo4: bar4",
111  };
112  BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
113 }
114 
115 BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
116 {
117  LogPrintf("foo5: %s\n", "bar5");
118  LogPrint(BCLog::NET, "foo6: %s\n", "bar6");
119  LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7");
120  LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8");
121  LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9");
122  LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10");
123  LogPrintfCategory(BCLog::VALIDATION, "foo11: %s\n", "bar11");
124  std::ifstream file{tmp_log_path};
125  std::vector<std::string> log_lines;
126  for (std::string log; std::getline(file, log);) {
127  log_lines.push_back(log);
128  }
129  std::vector<std::string> expected = {
130  "foo5: bar5",
131  "[net] foo6: bar6",
132  "[net:debug] foo7: bar7",
133  "[net:info] foo8: bar8",
134  "[net:warning] foo9: bar9",
135  "[net:error] foo10: bar10",
136  "[validation] foo11: bar11",
137  };
138  BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
139 }
140 
141 BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
142 {
144  const auto concatenated_category_names = LogInstance().LogCategoriesString();
145  std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
146  const auto category_names = SplitString(concatenated_category_names, ',');
147  for (const auto& category_name : category_names) {
148  BCLog::LogFlags category;
149  const auto trimmed_category_name = TrimString(category_name);
150  BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name));
151  expected_category_names.emplace_back(category, trimmed_category_name);
152  }
153 
154  std::vector<std::string> expected;
155  for (const auto& [category, name] : expected_category_names) {
156  LogPrint(category, "foo: %s\n", "bar");
157  std::string expected_log = "[";
158  expected_log += name;
159  expected_log += "] foo: bar";
160  expected.push_back(expected_log);
161  }
162 
163  std::ifstream file{tmp_log_path};
164  std::vector<std::string> log_lines;
165  for (std::string log; std::getline(file, log);) {
166  log_lines.push_back(log);
167  }
168  BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
169 }
170 
171 BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
172 {
174 
176  LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
177 
178  // Global log level
179  LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
180  LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
181  LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
182  LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
183 
184  // Category-specific log level
185  LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
186  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");
187  LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
188 
189  std::vector<std::string> expected = {
190  "[http:info] foo1: bar1",
191  "[validation:warning] foo3: bar3",
192  "[rpc:error] foo4: bar4",
193  "[net:warning] foo5: bar5",
194  "[net:error] foo7: bar7",
195  };
196  std::ifstream file{tmp_log_path};
197  std::vector<std::string> log_lines;
198  for (std::string log; std::getline(file, log);) {
199  log_lines.push_back(log);
200  }
201  BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
202 }
203 
205 {
206  // Set global log level
207  {
208  ResetLogger();
211  const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
212  std::string err;
213  BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
216  }
217 
218  // Set category-specific log level
219  {
220  ResetLogger();
223  const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
224  std::string err;
225  BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
228 
229  const auto& category_levels{LogInstance().CategoryLevels()};
230  const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
231  BOOST_REQUIRE(net_it != category_levels.end());
232  BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
233  }
234 
235  // Set both global log level and category-specific log level
236  {
237  ResetLogger();
240  const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
241  std::string err;
242  BOOST_REQUIRE(args.ParseParameters(4, argv_test, err));
245 
246  const auto& category_levels{LogInstance().CategoryLevels()};
247  BOOST_CHECK_EQUAL(category_levels.size(), 2);
248 
249  const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
250  BOOST_CHECK(net_it != category_levels.end());
251  BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
252 
253  const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
254  BOOST_CHECK(http_it != category_levels.end());
255  BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
256  }
257 }
258 
@ ALLOW_ANY
disable validation
Definition: system.h:180
bool ParseParameters(int argc, const char *const argv[], std::string &error)
Definition: system.cpp:300
void AddArg(const std::string &name, const std::string &help, unsigned int flags, const OptionsCategory &cat)
Add argument.
Definition: system.cpp:711
bool m_log_sourcelocations
Definition: logging.h:119
void SetLogLevel(Level level)
Definition: logging.h:169
fs::path m_file_path
Definition: logging.h:121
std::unordered_map< LogFlags, Level > CategoryLevels() const
Definition: logging.h:156
bool m_log_threadnames
Definition: logging.h:118
void EnableCategory(LogFlags flag)
Definition: logging.cpp:96
bool m_log_timestamps
Definition: logging.h:116
std::atomic< bool > m_reopen_file
Definition: logging.h:122
bool m_print_to_file
Definition: logging.h:114
void SetCategoryLogLevel(const std::unordered_map< LogFlags, Level > &levels)
Definition: logging.h:161
std::string LogCategoriesString() const
Returns a string with the log categories in alphabetical order.
Definition: logging.h:185
RAII-style object that outputs timing information to logs.
Definition: timer.h:23
Path class wrapper to block calls to the fs::path(std::string) implicit constructor and the fs::path:...
Definition: fs.h:31
BOOST_AUTO_TEST_SUITE_END()
Common init functions shared by bitcoin-node, bitcoin-wallet, etc.
bool GetLogCategory(BCLog::LogFlags &flag, const std::string &str)
Return true if str parses as a log category and set the flag.
Definition: logging.cpp:187
BCLog::Logger & LogInstance()
Definition: logging.cpp:20
#define LogPrintLevel(category, level,...)
Definition: logging.h:251
static void LogPrintf_(const std::string &logging_function, const std::string &source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, const char *fmt, const Args &... args)
Definition: logging.h:217
#define LogPrint(category,...)
Definition: logging.h:243
#define LogPrintfCategory(category,...)
Definition: logging.h:237
#define LogPrintf(...)
Definition: logging.h:234
BOOST_AUTO_TEST_CASE(logging_timer)
BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
static void ResetLogger()
Level
Definition: logging.h:71
LogFlags
Definition: logging.h:38
@ ALL
Definition: logging.h:69
@ RPC
Definition: logging.h:47
@ HTTP
Definition: logging.h:43
@ NONE
Definition: logging.h:39
@ VALIDATION
Definition: logging.h:61
@ MEMPOOL
Definition: logging.h:42
@ NET
Definition: logging.h:40
constexpr auto DEFAULT_LOG_LEVEL
Definition: logging.h:79
void SetLoggingLevel(const ArgsManager &args)
Definition: common.cpp:60
ArgsManager args
#define BOOST_CHECK_EQUAL(v1, v2)
Definition: object.cpp:17
#define BOOST_CHECK(expr)
Definition: object.cpp:16
const char * name
Definition: rest.cpp:46
std::string TrimString(std::string_view str, std::string_view pattern=" \f\n\r\t\v")
Definition: string.h:41
std::vector< std::string > SplitString(std::string_view str, char sep)
Definition: string.h:21
Basic testing setup.
Definition: setup_common.h:83
ArgsManager m_args
Definition: setup_common.h:90
fs::path tmp_log_path
bool prev_reopen_file
fs::path prev_log_path
std::unordered_map< BCLog::LogFlags, BCLog::Level > prev_category_levels
bool prev_print_to_file
BCLog::Level prev_log_level
bool prev_log_threadnames
bool prev_log_sourcelocations
bool prev_log_timestamps
void SetMockTime(int64_t nMockTimeIn)
DEPRECATED Use SetMockTime with chrono type.
Definition: time.cpp:91