Coverage Report

Created: 2024-10-21 15:10

/root/bitcoin/src/logging.cpp
Line
Count
Source (jump to first uncovered line)
1
// Copyright (c) 2009-2010 Satoshi Nakamoto
2
// Copyright (c) 2009-present The Bitcoin Core developers
3
// Distributed under the MIT software license, see the accompanying
4
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
5
6
#include <logging.h>
7
#include <memusage.h>
8
#include <util/check.h>
9
#include <util/fs.h>
10
#include <util/string.h>
11
#include <util/threadnames.h>
12
#include <util/time.h>
13
14
#include <array>
15
#include <map>
16
#include <optional>
17
18
using util::Join;
19
using util::RemovePrefixView;
20
21
const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
22
constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
23
24
BCLog::Logger& LogInstance()
25
0
{
26
/**
27
 * NOTE: the logger instances is leaked on exit. This is ugly, but will be
28
 * cleaned up by the OS/libc. Defining a logger as a global object doesn't work
29
 * since the order of destruction of static/global objects is undefined.
30
 * Consider if the logger gets destroyed, and then some later destructor calls
31
 * LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to
32
 * access the logger. When the shutdown sequence is fully audited and tested,
33
 * explicit destruction of these objects can be implemented by changing this
34
 * from a raw pointer to a std::unique_ptr.
35
 * Since the ~Logger() destructor is never called, the Logger class and all
36
 * its subclasses must have implicitly-defined destructors.
37
 *
38
 * This method of initialization was originally introduced in
39
 * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
40
 */
41
0
    static BCLog::Logger* g_logger{new BCLog::Logger()};
42
0
    return *g_logger;
43
0
}
44
45
bool fLogIPs = DEFAULT_LOGIPS;
46
47
static int FileWriteStr(std::string_view str, FILE *fp)
48
0
{
49
0
    return fwrite(str.data(), 1, str.size(), fp);
50
0
}
51
52
bool BCLog::Logger::StartLogging()
53
0
{
54
0
    StdLockGuard scoped_lock(m_cs);
55
56
0
    assert(m_buffering);
57
0
    assert(m_fileout == nullptr);
58
59
0
    if (m_print_to_file) {
60
0
        assert(!m_file_path.empty());
61
0
        m_fileout = fsbridge::fopen(m_file_path, "a");
62
0
        if (!m_fileout) {
63
0
            return false;
64
0
        }
65
66
0
        setbuf(m_fileout, nullptr); // unbuffered
67
68
        // Add newlines to the logfile to distinguish this execution from the
69
        // last one.
70
0
        FileWriteStr("\n\n\n\n\n", m_fileout);
71
0
    }
72
73
    // dump buffered messages from before we opened the log
74
0
    m_buffering = false;
75
0
    if (m_buffer_lines_discarded > 0) {
76
0
        LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), __func__, __FILE__, __LINE__, BCLog::ALL, Level::Info);
77
0
    }
78
0
    while (!m_msgs_before_open.empty()) {
79
0
        const auto& buflog = m_msgs_before_open.front();
80
0
        std::string s{buflog.str};
81
0
        FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_file, buflog.source_line, buflog.logging_function, buflog.threadname, buflog.now, buflog.mocktime);
82
0
        m_msgs_before_open.pop_front();
83
84
0
        if (m_print_to_file) FileWriteStr(s, m_fileout);
85
0
        if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
86
0
        for (const auto& cb : m_print_callbacks) {
87
0
            cb(s);
88
0
        }
89
0
    }
90
0
    m_cur_buffer_memusage = 0;
91
0
    if (m_print_to_console) fflush(stdout);
92
93
0
    return true;
94
0
}
95
96
void BCLog::Logger::DisconnectTestLogger()
97
0
{
98
0
    StdLockGuard scoped_lock(m_cs);
99
0
    m_buffering = true;
100
0
    if (m_fileout != nullptr) fclose(m_fileout);
101
0
    m_fileout = nullptr;
102
0
    m_print_callbacks.clear();
103
0
    m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
104
0
    m_cur_buffer_memusage = 0;
105
0
    m_buffer_lines_discarded = 0;
106
0
    m_msgs_before_open.clear();
107
0
}
108
109
void BCLog::Logger::DisableLogging()
110
0
{
111
0
    {
112
0
        StdLockGuard scoped_lock(m_cs);
113
0
        assert(m_buffering);
114
0
        assert(m_print_callbacks.empty());
115
0
    }
116
0
    m_print_to_file = false;
117
0
    m_print_to_console = false;
118
0
    StartLogging();
119
0
}
120
121
void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
122
0
{
123
0
    m_categories |= flag;
124
0
}
125
126
bool BCLog::Logger::EnableCategory(std::string_view str)
127
0
{
128
0
    BCLog::LogFlags flag;
129
0
    if (!GetLogCategory(flag, str)) return false;
130
0
    EnableCategory(flag);
131
0
    return true;
132
0
}
133
134
void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
135
0
{
136
0
    m_categories &= ~flag;
137
0
}
138
139
bool BCLog::Logger::DisableCategory(std::string_view str)
140
0
{
141
0
    BCLog::LogFlags flag;
142
0
    if (!GetLogCategory(flag, str)) return false;
143
0
    DisableCategory(flag);
144
0
    return true;
145
0
}
146
147
bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
148
0
{
149
0
    return (m_categories.load(std::memory_order_relaxed) & category) != 0;
150
0
}
151
152
bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
153
0
{
154
    // Log messages at Info, Warning and Error level unconditionally, so that
155
    // important troubleshooting information doesn't get lost.
156
0
    if (level >= BCLog::Level::Info) return true;
157
158
0
    if (!WillLogCategory(category)) return false;
159
160
0
    StdLockGuard scoped_lock(m_cs);
161
0
    const auto it{m_category_log_levels.find(category)};
162
0
    return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
163
0
}
164
165
bool BCLog::Logger::DefaultShrinkDebugFile() const
166
0
{
167
0
    return m_categories == BCLog::NONE;
168
0
}
169
170
static const std::map<std::string, BCLog::LogFlags, std::less<>> LOG_CATEGORIES_BY_STR{
171
    {"net", BCLog::NET},
172
    {"tor", BCLog::TOR},
173
    {"mempool", BCLog::MEMPOOL},
174
    {"http", BCLog::HTTP},
175
    {"bench", BCLog::BENCH},
176
    {"zmq", BCLog::ZMQ},
177
    {"walletdb", BCLog::WALLETDB},
178
    {"rpc", BCLog::RPC},
179
    {"estimatefee", BCLog::ESTIMATEFEE},
180
    {"addrman", BCLog::ADDRMAN},
181
    {"selectcoins", BCLog::SELECTCOINS},
182
    {"reindex", BCLog::REINDEX},
183
    {"cmpctblock", BCLog::CMPCTBLOCK},
184
    {"rand", BCLog::RAND},
185
    {"prune", BCLog::PRUNE},
186
    {"proxy", BCLog::PROXY},
187
    {"mempoolrej", BCLog::MEMPOOLREJ},
188
    {"libevent", BCLog::LIBEVENT},
189
    {"coindb", BCLog::COINDB},
190
    {"qt", BCLog::QT},
191
    {"leveldb", BCLog::LEVELDB},
192
    {"validation", BCLog::VALIDATION},
193
    {"i2p", BCLog::I2P},
194
    {"ipc", BCLog::IPC},
195
#ifdef DEBUG_LOCKCONTENTION
196
    {"lock", BCLog::LOCK},
197
#endif
198
    {"blockstorage", BCLog::BLOCKSTORAGE},
199
    {"txreconciliation", BCLog::TXRECONCILIATION},
200
    {"scan", BCLog::SCAN},
201
    {"txpackages", BCLog::TXPACKAGES},
202
};
203
204
static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
205
    // Swap keys and values from LOG_CATEGORIES_BY_STR.
206
0
    [](const auto& in) {
207
0
        std::unordered_map<BCLog::LogFlags, std::string> out;
208
0
        for (const auto& [k, v] : in) {
209
0
            const bool inserted{out.emplace(v, k).second};
210
0
            assert(inserted);
211
0
        }
212
0
        return out;
213
0
    }(LOG_CATEGORIES_BY_STR)
214
};
215
216
bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str)
217
0
{
218
0
    if (str.empty() || str == "1" || str == "all") {
219
0
        flag = BCLog::ALL;
220
0
        return true;
221
0
    }
222
0
    auto it = LOG_CATEGORIES_BY_STR.find(str);
223
0
    if (it != LOG_CATEGORIES_BY_STR.end()) {
224
0
        flag = it->second;
225
0
        return true;
226
0
    }
227
0
    return false;
228
0
}
229
230
std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
231
0
{
232
0
    switch (level) {
233
0
    case BCLog::Level::Trace:
234
0
        return "trace";
235
0
    case BCLog::Level::Debug:
236
0
        return "debug";
237
0
    case BCLog::Level::Info:
238
0
        return "info";
239
0
    case BCLog::Level::Warning:
240
0
        return "warning";
241
0
    case BCLog::Level::Error:
242
0
        return "error";
243
0
    }
244
0
    assert(false);
245
0
}
246
247
static std::string LogCategoryToStr(BCLog::LogFlags category)
248
0
{
249
0
    if (category == BCLog::ALL) {
250
0
        return "all";
251
0
    }
252
0
    auto it = LOG_CATEGORIES_BY_FLAG.find(category);
253
0
    assert(it != LOG_CATEGORIES_BY_FLAG.end());
254
0
    return it->second;
255
0
}
256
257
static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str)
258
0
{
259
0
    if (level_str == "trace") {
260
0
        return BCLog::Level::Trace;
261
0
    } else if (level_str == "debug") {
262
0
        return BCLog::Level::Debug;
263
0
    } else if (level_str == "info") {
264
0
        return BCLog::Level::Info;
265
0
    } else if (level_str == "warning") {
266
0
        return BCLog::Level::Warning;
267
0
    } else if (level_str == "error") {
268
0
        return BCLog::Level::Error;
269
0
    } else {
270
0
        return std::nullopt;
271
0
    }
272
0
}
273
274
std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
275
0
{
276
0
    std::vector<LogCategory> ret;
277
0
    ret.reserve(LOG_CATEGORIES_BY_STR.size());
278
0
    for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
279
0
        ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
280
0
    }
281
0
    return ret;
282
0
}
283
284
/** Log severity levels that can be selected by the user. */
285
static constexpr std::array<BCLog::Level, 3> LogLevelsList()
286
0
{
287
0
    return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
288
0
}
289
290
std::string BCLog::Logger::LogLevelsString() const
291
0
{
292
0
    const auto& levels = LogLevelsList();
293
0
    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
294
0
}
295
296
std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const
297
0
{
298
0
    std::string strStamped;
299
300
0
    if (!m_log_timestamps)
301
0
        return strStamped;
302
303
0
    const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
304
0
    strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
305
0
    if (m_log_time_micros && !strStamped.empty()) {
306
0
        strStamped.pop_back();
307
0
        strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
308
0
    }
309
0
    if (mocktime > 0s) {
310
0
        strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
311
0
    }
312
0
    strStamped += ' ';
313
314
0
    return strStamped;
315
0
}
316
317
namespace BCLog {
318
    /** Belts and suspenders: make sure outgoing log messages don't contain
319
     * potentially suspicious characters, such as terminal control codes.
320
     *
321
     * This escapes control characters except newline ('\n') in C syntax.
322
     * It escapes instead of removes them to still allow for troubleshooting
323
     * issues where they accidentally end up in strings.
324
     */
325
0
    std::string LogEscapeMessage(std::string_view str) {
326
0
        std::string ret;
327
0
        for (char ch_in : str) {
328
0
            uint8_t ch = (uint8_t)ch_in;
329
0
            if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
330
0
                ret += ch_in;
331
0
            } else {
332
0
                ret += strprintf("\\x%02x", ch);
333
0
            }
334
0
        }
335
0
        return ret;
336
0
    }
337
} // namespace BCLog
338
339
std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
340
0
{
341
0
    if (category == LogFlags::NONE) category = LogFlags::ALL;
342
343
0
    const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
344
345
    // If there is no category, Info is implied
346
0
    if (!has_category && level == Level::Info) return {};
347
348
0
    std::string s{"["};
349
0
    if (has_category) {
350
0
        s += LogCategoryToStr(category);
351
0
    }
352
353
0
    if (m_always_print_category_level || !has_category || level != Level::Debug) {
354
        // If there is a category, Debug is implied, so don't add the level
355
356
        // Only add separator if we have a category
357
0
        if (has_category) s += ":";
358
0
        s += Logger::LogLevelToStr(level);
359
0
    }
360
361
0
    s += "] ";
362
0
    return s;
363
0
}
364
365
static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
366
0
{
367
0
    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
368
0
}
369
370
void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
371
0
{
372
0
    if (!str.ends_with('\n')) str.push_back('\n');
373
374
0
    str.insert(0, GetLogPrefix(category, level));
375
376
0
    if (m_log_sourcelocations) {
377
0
        str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_file, "./"), source_line, logging_function));
378
0
    }
379
380
0
    if (m_log_threadnames) {
381
0
        str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname)));
382
0
    }
383
384
0
    str.insert(0, LogTimestampStr(now, mocktime));
385
0
}
386
387
void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
388
0
{
389
0
    StdLockGuard scoped_lock(m_cs);
390
0
    return LogPrintStr_(str, logging_function, source_file, source_line, category, level);
391
0
}
392
393
void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
394
0
{
395
0
    std::string str_prefixed = LogEscapeMessage(str);
396
397
0
    if (m_buffering) {
398
0
        {
399
0
            BufferedLog buf{
400
0
                .now=SystemClock::now(),
401
0
                .mocktime=GetMockTime(),
402
0
                .str=str_prefixed,
403
0
                .logging_function=std::string(logging_function),
404
0
                .source_file=std::string(source_file),
405
0
                .threadname=util::ThreadGetInternalName(),
406
0
                .source_line=source_line,
407
0
                .category=category,
408
0
                .level=level,
409
0
            };
410
0
            m_cur_buffer_memusage += MemUsage(buf);
411
0
            m_msgs_before_open.push_back(std::move(buf));
412
0
        }
413
414
0
        while (m_cur_buffer_memusage > m_max_buffer_memusage) {
415
0
            if (m_msgs_before_open.empty()) {
416
0
                m_cur_buffer_memusage = 0;
417
0
                break;
418
0
            }
419
0
            m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
420
0
            m_msgs_before_open.pop_front();
421
0
            ++m_buffer_lines_discarded;
422
0
        }
423
424
0
        return;
425
0
    }
426
427
0
    FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
428
429
0
    if (m_print_to_console) {
430
        // print to console
431
0
        fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
432
0
        fflush(stdout);
433
0
    }
434
0
    for (const auto& cb : m_print_callbacks) {
435
0
        cb(str_prefixed);
436
0
    }
437
0
    if (m_print_to_file) {
438
0
        assert(m_fileout != nullptr);
439
440
        // reopen the log file, if requested
441
0
        if (m_reopen_file) {
442
0
            m_reopen_file = false;
443
0
            FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
444
0
            if (new_fileout) {
445
0
                setbuf(new_fileout, nullptr); // unbuffered
446
0
                fclose(m_fileout);
447
0
                m_fileout = new_fileout;
448
0
            }
449
0
        }
450
0
        FileWriteStr(str_prefixed, m_fileout);
451
0
    }
452
0
}
453
454
void BCLog::Logger::ShrinkDebugFile()
455
0
{
456
    // Amount of debug.log to save at end when shrinking (must fit in memory)
457
0
    constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
458
459
0
    assert(!m_file_path.empty());
460
461
    // Scroll debug.log if it's getting too big
462
0
    FILE* file = fsbridge::fopen(m_file_path, "r");
463
464
    // Special files (e.g. device nodes) may not have a size.
465
0
    size_t log_size = 0;
466
0
    try {
467
0
        log_size = fs::file_size(m_file_path);
468
0
    } catch (const fs::filesystem_error&) {}
469
470
    // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
471
    // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
472
0
    if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
473
0
    {
474
        // Restart the file with some of the end
475
0
        std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
476
0
        if (fseek(file, -((long)vch.size()), SEEK_END)) {
477
0
            LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
478
0
            fclose(file);
479
0
            return;
480
0
        }
481
0
        int nBytes = fread(vch.data(), 1, vch.size(), file);
482
0
        fclose(file);
483
484
0
        file = fsbridge::fopen(m_file_path, "w");
485
0
        if (file)
486
0
        {
487
0
            fwrite(vch.data(), 1, nBytes, file);
488
0
            fclose(file);
489
0
        }
490
0
    }
491
0
    else if (file != nullptr)
492
0
        fclose(file);
493
0
}
494
495
bool BCLog::Logger::SetLogLevel(std::string_view level_str)
496
0
{
497
0
    const auto level = GetLogLevel(level_str);
498
0
    if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
499
0
    m_log_level = level.value();
500
0
    return true;
501
0
}
502
503
bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str)
504
0
{
505
0
    BCLog::LogFlags flag;
506
0
    if (!GetLogCategory(flag, category_str)) return false;
507
508
0
    const auto level = GetLogLevel(level_str);
509
0
    if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
510
511
0
    StdLockGuard scoped_lock(m_cs);
512
0
    m_category_log_levels[flag] = level.value();
513
0
    return true;
514
0
}