2018-04-18 19:05:05 +02:00
|
|
|
// Copyright (c) 2009-2010 Satoshi Nakamoto
|
|
|
|
// Copyright (c) 2009-2018 The Bitcoin Core developers
|
|
|
|
// Distributed under the MIT software license, see the accompanying
|
|
|
|
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
|
|
|
|
|
|
|
|
#include <logging.h>
|
2018-05-05 20:14:43 +02:00
|
|
|
#include <util/threadnames.h>
|
2018-10-23 00:51:11 +02:00
|
|
|
#include <util/time.h>
|
2018-04-18 19:05:05 +02:00
|
|
|
|
2018-05-05 20:14:43 +02:00
|
|
|
#include <mutex>
|
|
|
|
|
2018-04-18 19:05:05 +02:00
|
|
|
const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
|
|
|
|
|
2019-01-25 21:54:49 +01:00
|
|
|
BCLog::Logger& LogInstance()
|
|
|
|
{
|
2018-04-11 19:03:21 +02:00
|
|
|
/**
|
|
|
|
* NOTE: the logger instances is leaked on exit. This is ugly, but will be
|
|
|
|
* cleaned up by the OS/libc. Defining a logger as a global object doesn't work
|
|
|
|
* since the order of destruction of static/global objects is undefined.
|
|
|
|
* Consider if the logger gets destroyed, and then some later destructor calls
|
|
|
|
* LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to
|
|
|
|
* access the logger. When the shutdown sequence is fully audited and tested,
|
|
|
|
* explicit destruction of these objects can be implemented by changing this
|
|
|
|
* from a raw pointer to a std::unique_ptr.
|
2019-01-25 21:54:49 +01:00
|
|
|
* Since the destructor is never called, the logger and all its members must
|
|
|
|
* have a trivial destructor.
|
2018-04-11 19:03:21 +02:00
|
|
|
*
|
|
|
|
* This method of initialization was originally introduced in
|
|
|
|
* ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
|
|
|
|
*/
|
2019-01-25 21:54:49 +01:00
|
|
|
static BCLog::Logger* g_logger{new BCLog::Logger()};
|
|
|
|
return *g_logger;
|
|
|
|
}
|
2018-04-18 19:05:05 +02:00
|
|
|
|
|
|
|
bool fLogIPs = DEFAULT_LOGIPS;
|
|
|
|
|
|
|
|
static int FileWriteStr(const std::string &str, FILE *fp)
|
|
|
|
{
|
|
|
|
return fwrite(str.data(), 1, str.size(), fp);
|
|
|
|
}
|
|
|
|
|
2018-04-11 20:12:51 +02:00
|
|
|
bool BCLog::Logger::OpenDebugLog()
|
2018-04-18 19:05:05 +02:00
|
|
|
{
|
2018-04-20 09:42:32 +02:00
|
|
|
std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
|
2018-04-18 19:05:05 +02:00
|
|
|
|
2018-04-20 09:42:32 +02:00
|
|
|
assert(m_fileout == nullptr);
|
2018-04-20 10:11:44 +02:00
|
|
|
assert(!m_file_path.empty());
|
2018-04-18 19:05:05 +02:00
|
|
|
|
2018-04-20 10:11:44 +02:00
|
|
|
m_fileout = fsbridge::fopen(m_file_path, "a");
|
2018-04-20 09:42:32 +02:00
|
|
|
if (!m_fileout) {
|
2018-04-18 19:05:05 +02:00
|
|
|
return false;
|
|
|
|
}
|
|
|
|
|
2018-04-20 09:42:32 +02:00
|
|
|
setbuf(m_fileout, nullptr); // unbuffered
|
2018-04-18 19:05:05 +02:00
|
|
|
// dump buffered messages from before we opened the log
|
2018-04-20 09:42:32 +02:00
|
|
|
while (!m_msgs_before_open.empty()) {
|
|
|
|
FileWriteStr(m_msgs_before_open.front(), m_fileout);
|
|
|
|
m_msgs_before_open.pop_front();
|
2018-04-18 19:05:05 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
2018-04-11 22:02:01 +02:00
|
|
|
void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
|
|
|
|
{
|
2018-04-20 09:42:32 +02:00
|
|
|
m_categories |= flag;
|
2018-04-11 22:02:01 +02:00
|
|
|
}
|
|
|
|
|
2018-04-11 23:06:35 +02:00
|
|
|
bool BCLog::Logger::EnableCategory(const std::string& str)
|
|
|
|
{
|
|
|
|
BCLog::LogFlags flag;
|
|
|
|
if (!GetLogCategory(flag, str)) return false;
|
|
|
|
EnableCategory(flag);
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
2018-04-11 22:02:01 +02:00
|
|
|
void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
|
|
|
|
{
|
2018-04-20 09:42:32 +02:00
|
|
|
m_categories &= ~flag;
|
2018-04-11 22:02:01 +02:00
|
|
|
}
|
|
|
|
|
2018-04-11 23:06:35 +02:00
|
|
|
bool BCLog::Logger::DisableCategory(const std::string& str)
|
|
|
|
{
|
|
|
|
BCLog::LogFlags flag;
|
|
|
|
if (!GetLogCategory(flag, str)) return false;
|
|
|
|
DisableCategory(flag);
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
2018-04-11 22:02:01 +02:00
|
|
|
bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
|
|
|
|
{
|
2018-04-20 09:42:32 +02:00
|
|
|
return (m_categories.load(std::memory_order_relaxed) & category) != 0;
|
2018-04-11 22:02:01 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
bool BCLog::Logger::DefaultShrinkDebugFile() const
|
|
|
|
{
|
2018-04-20 09:42:32 +02:00
|
|
|
return m_categories == BCLog::NONE;
|
2018-04-11 22:02:01 +02:00
|
|
|
}
|
|
|
|
|
2018-04-18 19:05:05 +02:00
|
|
|
struct CLogCategoryDesc
|
|
|
|
{
|
2018-04-11 23:06:35 +02:00
|
|
|
BCLog::LogFlags flag;
|
2018-04-18 19:05:05 +02:00
|
|
|
std::string category;
|
|
|
|
};
|
|
|
|
|
|
|
|
const CLogCategoryDesc LogCategories[] =
|
|
|
|
{
|
|
|
|
{BCLog::NONE, "0"},
|
|
|
|
{BCLog::NONE, "none"},
|
|
|
|
{BCLog::NET, "net"},
|
|
|
|
{BCLog::TOR, "tor"},
|
|
|
|
{BCLog::MEMPOOL, "mempool"},
|
|
|
|
{BCLog::HTTP, "http"},
|
|
|
|
{BCLog::BENCH, "bench"},
|
|
|
|
{BCLog::ZMQ, "zmq"},
|
|
|
|
{BCLog::DB, "db"},
|
|
|
|
{BCLog::RPC, "rpc"},
|
|
|
|
{BCLog::ESTIMATEFEE, "estimatefee"},
|
|
|
|
{BCLog::ADDRMAN, "addrman"},
|
|
|
|
{BCLog::SELECTCOINS, "selectcoins"},
|
|
|
|
{BCLog::REINDEX, "reindex"},
|
|
|
|
{BCLog::CMPCTBLOCK, "cmpctblock"},
|
|
|
|
{BCLog::RAND, "rand"},
|
|
|
|
{BCLog::PRUNE, "prune"},
|
|
|
|
{BCLog::PROXY, "proxy"},
|
|
|
|
{BCLog::MEMPOOLREJ, "mempoolrej"},
|
|
|
|
{BCLog::LIBEVENT, "libevent"},
|
|
|
|
{BCLog::COINDB, "coindb"},
|
|
|
|
{BCLog::QT, "qt"},
|
|
|
|
{BCLog::LEVELDB, "leveldb"},
|
|
|
|
{BCLog::ALL, "1"},
|
|
|
|
{BCLog::ALL, "all"},
|
|
|
|
};
|
|
|
|
|
2018-04-11 23:06:35 +02:00
|
|
|
bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
|
2018-04-18 19:05:05 +02:00
|
|
|
{
|
2018-04-11 23:06:35 +02:00
|
|
|
if (str == "") {
|
|
|
|
flag = BCLog::ALL;
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
for (const CLogCategoryDesc& category_desc : LogCategories) {
|
|
|
|
if (category_desc.category == str) {
|
|
|
|
flag = category_desc.flag;
|
2018-04-18 19:05:05 +02:00
|
|
|
return true;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
|
|
|
|
std::string ListLogCategories()
|
|
|
|
{
|
|
|
|
std::string ret;
|
|
|
|
int outcount = 0;
|
2018-04-11 23:06:35 +02:00
|
|
|
for (const CLogCategoryDesc& category_desc : LogCategories) {
|
2018-04-18 19:05:05 +02:00
|
|
|
// Omit the special cases.
|
2018-04-11 23:06:35 +02:00
|
|
|
if (category_desc.flag != BCLog::NONE && category_desc.flag != BCLog::ALL) {
|
2018-04-18 19:05:05 +02:00
|
|
|
if (outcount != 0) ret += ", ";
|
2018-04-11 23:06:35 +02:00
|
|
|
ret += category_desc.category;
|
2018-04-18 19:05:05 +02:00
|
|
|
outcount++;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
|
|
|
std::vector<CLogCategoryActive> ListActiveLogCategories()
|
|
|
|
{
|
|
|
|
std::vector<CLogCategoryActive> ret;
|
2018-04-11 23:06:35 +02:00
|
|
|
for (const CLogCategoryDesc& category_desc : LogCategories) {
|
2018-04-18 19:05:05 +02:00
|
|
|
// Omit the special cases.
|
2018-04-11 23:06:35 +02:00
|
|
|
if (category_desc.flag != BCLog::NONE && category_desc.flag != BCLog::ALL) {
|
2018-04-18 19:05:05 +02:00
|
|
|
CLogCategoryActive catActive;
|
2018-04-11 23:06:35 +02:00
|
|
|
catActive.category = category_desc.category;
|
|
|
|
catActive.active = LogAcceptCategory(category_desc.flag);
|
2018-04-18 19:05:05 +02:00
|
|
|
ret.push_back(catActive);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
2018-05-05 20:14:43 +02:00
|
|
|
std::string BCLog::Logger::LogTimestampStr(const std::string& str)
|
2018-04-18 19:05:05 +02:00
|
|
|
{
|
|
|
|
std::string strStamped;
|
|
|
|
|
2018-04-20 09:42:32 +02:00
|
|
|
if (!m_log_timestamps)
|
2018-04-18 19:05:05 +02:00
|
|
|
return str;
|
|
|
|
|
2018-04-20 09:42:32 +02:00
|
|
|
if (m_started_new_line) {
|
2018-04-18 19:05:05 +02:00
|
|
|
int64_t nTimeMicros = GetTimeMicros();
|
|
|
|
strStamped = FormatISO8601DateTime(nTimeMicros/1000000);
|
2018-04-20 09:42:32 +02:00
|
|
|
if (m_log_time_micros) {
|
2018-04-18 19:05:05 +02:00
|
|
|
strStamped.pop_back();
|
|
|
|
strStamped += strprintf(".%06dZ", nTimeMicros%1000000);
|
|
|
|
}
|
|
|
|
int64_t mocktime = GetMockTime();
|
|
|
|
if (mocktime) {
|
|
|
|
strStamped += " (mocktime: " + FormatISO8601DateTime(mocktime) + ")";
|
|
|
|
}
|
|
|
|
strStamped += ' ' + str;
|
|
|
|
} else
|
|
|
|
strStamped = str;
|
|
|
|
|
|
|
|
return strStamped;
|
|
|
|
}
|
|
|
|
|
2018-05-02 11:25:20 +02:00
|
|
|
void BCLog::Logger::LogPrintStr(const std::string &str)
|
2018-04-18 19:05:05 +02:00
|
|
|
{
|
2018-05-05 20:14:43 +02:00
|
|
|
std::string str_prefixed = str;
|
|
|
|
|
|
|
|
if (m_log_threadnames && m_started_new_line) {
|
|
|
|
str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
|
|
|
|
}
|
|
|
|
|
|
|
|
str_prefixed = LogTimestampStr(str_prefixed);
|
|
|
|
|
|
|
|
m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
|
2018-04-18 19:05:05 +02:00
|
|
|
|
2018-04-20 09:42:32 +02:00
|
|
|
if (m_print_to_console) {
|
2018-04-18 19:05:05 +02:00
|
|
|
// print to console
|
2018-05-05 20:14:43 +02:00
|
|
|
fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
|
2018-04-18 19:05:05 +02:00
|
|
|
fflush(stdout);
|
|
|
|
}
|
2018-04-20 09:42:32 +02:00
|
|
|
if (m_print_to_file) {
|
|
|
|
std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
|
2018-04-18 19:05:05 +02:00
|
|
|
|
|
|
|
// buffer if we haven't opened the log yet
|
2018-04-20 09:42:32 +02:00
|
|
|
if (m_fileout == nullptr) {
|
2018-05-05 20:14:43 +02:00
|
|
|
m_msgs_before_open.push_back(str_prefixed);
|
2018-04-18 19:05:05 +02:00
|
|
|
}
|
|
|
|
else
|
|
|
|
{
|
|
|
|
// reopen the log file, if requested
|
2018-04-20 09:42:32 +02:00
|
|
|
if (m_reopen_file) {
|
|
|
|
m_reopen_file = false;
|
2018-05-03 18:04:58 +02:00
|
|
|
FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
|
|
|
|
if (new_fileout) {
|
|
|
|
setbuf(new_fileout, nullptr); // unbuffered
|
|
|
|
fclose(m_fileout);
|
|
|
|
m_fileout = new_fileout;
|
2018-05-02 10:43:17 +02:00
|
|
|
}
|
2018-04-18 19:05:05 +02:00
|
|
|
}
|
2018-05-05 20:14:43 +02:00
|
|
|
FileWriteStr(str_prefixed, m_fileout);
|
2018-04-18 19:05:05 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-04-11 20:12:51 +02:00
|
|
|
void BCLog::Logger::ShrinkDebugFile()
|
2018-04-18 19:05:05 +02:00
|
|
|
{
|
|
|
|
// Amount of debug.log to save at end when shrinking (must fit in memory)
|
|
|
|
constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
|
2018-04-20 10:11:44 +02:00
|
|
|
|
|
|
|
assert(!m_file_path.empty());
|
|
|
|
|
2018-04-18 19:05:05 +02:00
|
|
|
// Scroll debug.log if it's getting too big
|
2018-04-20 10:11:44 +02:00
|
|
|
FILE* file = fsbridge::fopen(m_file_path, "r");
|
2018-04-18 19:05:05 +02:00
|
|
|
|
|
|
|
// Special files (e.g. device nodes) may not have a size.
|
|
|
|
size_t log_size = 0;
|
|
|
|
try {
|
2018-04-20 10:11:44 +02:00
|
|
|
log_size = fs::file_size(m_file_path);
|
2018-08-15 15:05:21 +02:00
|
|
|
} catch (const fs::filesystem_error&) {}
|
2018-04-18 19:05:05 +02:00
|
|
|
|
|
|
|
// If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
|
|
|
|
// trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
|
|
|
|
if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
|
|
|
|
{
|
|
|
|
// Restart the file with some of the end
|
|
|
|
std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
|
2018-05-02 12:12:55 +02:00
|
|
|
if (fseek(file, -((long)vch.size()), SEEK_END)) {
|
2018-05-03 15:44:04 +02:00
|
|
|
LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
|
2018-05-02 12:12:55 +02:00
|
|
|
fclose(file);
|
|
|
|
return;
|
|
|
|
}
|
2018-04-18 19:05:05 +02:00
|
|
|
int nBytes = fread(vch.data(), 1, vch.size(), file);
|
|
|
|
fclose(file);
|
|
|
|
|
2018-04-20 10:11:44 +02:00
|
|
|
file = fsbridge::fopen(m_file_path, "w");
|
2018-04-18 19:05:05 +02:00
|
|
|
if (file)
|
|
|
|
{
|
|
|
|
fwrite(vch.data(), 1, nBytes, file);
|
|
|
|
fclose(file);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
else if (file != nullptr)
|
|
|
|
fclose(file);
|
|
|
|
}
|