Inside Bitcoin

1// Copyright (c) 2019-present 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/common.h>
10#include <test/util/logging.h>
11#include <test/util/setup_common.h>
12#include <tinyformat.h>
13#include <util/fs.h>
14#include <util/fs_helpers.h>
15#include <util/string.h>
16
17#include <chrono>
18#include <fstream>
19#include <future>
20#include <ios>
21#include <iostream>
22#include <source_location>
23#include <string>
24#include <unordered_map>
25#include <utility>
26#include <vector>
27
28#include <boost/test/unit_test.hpp>
29
30using util::SplitString;
31using util::TrimString;
32
33BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
34
35static void ResetLogger()
36{
37    LogInstance().SetLogLevel(BCLog::DEFAULT_LOG_LEVEL);
38    LogInstance().SetCategoryLogLevel({});
39}
40
41static std::vector<std::string> ReadDebugLogLines()
42{
43    std::vector<std::string> lines;
44    std::ifstream ifs{LogInstance().m_file_path.std_path()};
45    for (std::string line; std::getline(ifs, line);) {
46        lines.push_back(std::move(line));
47    }
48    return lines;
49}
50
51struct LogSetup : public BasicTestingSetup {
52    fs::path prev_log_path;
53    fs::path tmp_log_path;
54    bool prev_reopen_file;
55    bool prev_print_to_file;
56    bool prev_log_timestamps;
57    bool prev_log_threadnames;
58    bool prev_log_sourcelocations;
59    std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
60    BCLog::Level prev_log_level;
61    BCLog::CategoryMask prev_category_mask;
62
63    LogSetup() : prev_log_path{LogInstance().m_file_path},
64                 tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
65                 prev_reopen_file{LogInstance().m_reopen_file},
66                 prev_print_to_file{LogInstance().m_print_to_file},
67                 prev_log_timestamps{LogInstance().m_log_timestamps},
68                 prev_log_threadnames{LogInstance().m_log_threadnames},
69                 prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
70                 prev_category_levels{LogInstance().CategoryLevels()},
71                 prev_log_level{LogInstance().LogLevel()},
72                 prev_category_mask{LogInstance().GetCategoryMask()}
73    {
74        LogInstance().m_file_path = tmp_log_path;
75        LogInstance().m_reopen_file = true;
76        LogInstance().m_print_to_file = true;
77        LogInstance().m_log_timestamps = false;
78        LogInstance().m_log_threadnames = false;
79
80        // Prevent tests from failing when the line number of the logs changes.
81        LogInstance().m_log_sourcelocations = false;
82
83        LogInstance().SetLogLevel(BCLog::Level::Debug);
84        LogInstance().DisableCategory(BCLog::LogFlags::ALL);
85        LogInstance().SetCategoryLogLevel({});
86        LogInstance().SetRateLimiting(nullptr);
87    }
88
89    ~LogSetup()
90    {
91        LogInstance().m_file_path = prev_log_path;
92        LogInfo("Sentinel log to reopen log file");
93        LogInstance().m_print_to_file = prev_print_to_file;
94        LogInstance().m_reopen_file = prev_reopen_file;
95        LogInstance().m_log_timestamps = prev_log_timestamps;
96        LogInstance().m_log_threadnames = prev_log_threadnames;
97        LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
98        LogInstance().SetLogLevel(prev_log_level);
99        LogInstance().SetCategoryLogLevel(prev_category_levels);
100        LogInstance().SetRateLimiting(nullptr);
101        LogInstance().DisableCategory(BCLog::LogFlags::ALL);
102        LogInstance().EnableCategory(BCLog::LogFlags{prev_category_mask});
103    }
104};
105
106BOOST_AUTO_TEST_CASE(logging_timer)
107{
108    auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
109    const std::string_view result_prefix{"tests: msg ("};
110    BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);
111}
112
113BOOST_FIXTURE_TEST_CASE(logging_LogPrint, LogSetup)
114{
115    LogInstance().m_log_sourcelocations = true;
116
117    struct Case {
118        std::string msg;
119        BCLog::LogFlags category;
120        BCLog::Level level;
121        std::string prefix;
122        SourceLocation loc;
123    };
124
125    std::vector<Case> cases = {
126        {"foo1: bar1", BCLog::NET, BCLog::Level::Debug, "[net] ", SourceLocation{__func__}},
127        {"foo2: bar2", BCLog::NET, BCLog::Level::Info, "[net:info] ", SourceLocation{__func__}},
128        {"foo3: bar3", BCLog::ALL, BCLog::Level::Debug, "[debug] ", SourceLocation{__func__}},
129        {"foo4: bar4", BCLog::ALL, BCLog::Level::Info, "", SourceLocation{__func__}},
130        {"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ", SourceLocation{__func__}},
131        {"foo6: bar6", BCLog::NONE, BCLog::Level::Info, "", SourceLocation{__func__}},
132    };
133
134    std::vector<std::string> expected;
135    for (auto& [msg, category, level, prefix, loc] : cases) {
136        expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name_short(), prefix, msg));
137        LogInstance().LogPrint({.category = category, .level = level, .should_ratelimit = false, .source_loc = std::move(loc), .message = msg});
138    }
139    std::vector<std::string> log_lines{ReadDebugLogLines()};
140    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
141}
142
143BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
144{
145    LogInstance().EnableCategory(BCLog::NET);
146    LogTrace(BCLog::NET, "foo6: %s", "bar6"); // not logged
147    LogDebug(BCLog::NET, "foo7: %s", "bar7");
148    LogInfo("foo8: %s", "bar8");
149    LogWarning("foo9: %s", "bar9");
150    LogError("foo10: %s", "bar10");
151    std::vector<std::string> log_lines{ReadDebugLogLines()};
152    std::vector<std::string> expected = {
153        "[net] foo7: bar7",
154        "foo8: bar8",
155        "[warning] foo9: bar9",
156        "[error] foo10: bar10",
157    };
158    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
159}
160
161BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
162{
163    LogInstance().EnableCategory(BCLog::LogFlags::ALL);
164    const auto concatenated_category_names = LogInstance().LogCategoriesString();
165    std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
166    const auto category_names = SplitString(concatenated_category_names, ',');
167    for (const auto& category_name : category_names) {
168        const auto trimmed_category_name = TrimString(category_name);
169        const auto category{*Assert(BCLog::Logger::GetLogCategory(trimmed_category_name))};
170        expected_category_names.emplace_back(category, trimmed_category_name);
171    }
172
173    std::vector<std::string> expected;
174    for (const auto& [category, name] : expected_category_names) {
175        LogDebug(category, "foo: %s\n", "bar");
176        std::string expected_log = "[";
177        expected_log += name;
178        expected_log += "] foo: bar";
179        expected.push_back(expected_log);
180    }
181
182    std::vector<std::string> log_lines{ReadDebugLogLines()};
183    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
184}
185
186BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
187{
188    LogInstance().SetLogLevel(BCLog::Level::Debug);
189    LogInstance().EnableCategory(BCLog::LogFlags::ALL);
190    LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
191
192    // Global log level
193    LogInfo("info_%s", 1);
194    LogTrace(BCLog::HTTP, "trace_%s. This log level is lower than the global one.", 2);
195    LogDebug(BCLog::HTTP, "debug_%s", 3);
196    LogWarning("warn_%s", 4);
197    LogError("err_%s", 5);
198
199    // Category-specific log level
200    LogDebug(BCLog::NET, "debug_%s. This log level is the same as the global one but lower than the category-specific one, which takes precedence.", 6);
201
202    std::vector<std::string> expected = {
203        "info_1",
204        "[http] debug_3",
205        "[warning] warn_4",
206        "[error] err_5",
207    };
208    std::vector<std::string> log_lines{ReadDebugLogLines()};
209    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
210}
211
212BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
213{
214    // Set global log level
215    {
216        ResetLogger();
217        ArgsManager args;
218        args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
219        const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
220        std::string err;
221        BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
222
223        auto result = init::SetLoggingLevel(args);
224        BOOST_REQUIRE(result);
225        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
226    }
227
228    // Set category-specific log level
229    {
230        ResetLogger();
231        ArgsManager args;
232        args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
233        const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
234        std::string err;
235        BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
236
237        auto result = init::SetLoggingLevel(args);
238        BOOST_REQUIRE(result);
239        BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL);
240
241        const auto& category_levels{LogInstance().CategoryLevels()};
242        const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
243        BOOST_REQUIRE(net_it != category_levels.end());
244        BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
245    }
246
247    // Set both global log level and category-specific log level
248    {
249        ResetLogger();
250        ArgsManager args;