Branch data Line data Source code
# 1 : : // Copyright (c) 2009-2010 Satoshi Nakamoto
# 2 : : // Copyright (c) 2009-2021 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 <fs.h>
# 7 : : #include <logging.h>
# 8 : : #include <util/threadnames.h>
# 9 : : #include <util/string.h>
# 10 : : #include <util/time.h>
# 11 : :
# 12 : : #include <algorithm>
# 13 : : #include <array>
# 14 : : #include <mutex>
# 15 : :
# 16 : : const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
# 17 : :
# 18 : : BCLog::Logger& LogInstance()
# 19 : 7947189 : {
# 20 : : /**
# 21 : : * NOTE: the logger instances is leaked on exit. This is ugly, but will be
# 22 : : * cleaned up by the OS/libc. Defining a logger as a global object doesn't work
# 23 : : * since the order of destruction of static/global objects is undefined.
# 24 : : * Consider if the logger gets destroyed, and then some later destructor calls
# 25 : : * LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to
# 26 : : * access the logger. When the shutdown sequence is fully audited and tested,
# 27 : : * explicit destruction of these objects can be implemented by changing this
# 28 : : * from a raw pointer to a std::unique_ptr.
# 29 : : * Since the ~Logger() destructor is never called, the Logger class and all
# 30 : : * its subclasses must have implicitly-defined destructors.
# 31 : : *
# 32 : : * This method of initialization was originally introduced in
# 33 : : * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
# 34 : : */
# 35 : 7947189 : static BCLog::Logger* g_logger{new BCLog::Logger()};
# 36 : 7947189 : return *g_logger;
# 37 : 7947189 : }
# 38 : :
# 39 : : bool fLogIPs = DEFAULT_LOGIPS;
# 40 : :
# 41 : : static int FileWriteStr(const std::string &str, FILE *fp)
# 42 : 2727925 : {
# 43 : 2727925 : return fwrite(str.data(), 1, str.size(), fp);
# 44 : 2727925 : }
# 45 : :
# 46 : : bool BCLog::Logger::StartLogging()
# 47 : 1631 : {
# 48 : 1631 : StdLockGuard scoped_lock(m_cs);
# 49 : :
# 50 : 1631 : assert(m_buffering);
# 51 : 0 : assert(m_fileout == nullptr);
# 52 : :
# 53 [ + + ]: 1631 : if (m_print_to_file) {
# 54 : 1630 : assert(!m_file_path.empty());
# 55 : 0 : m_fileout = fsbridge::fopen(m_file_path, "a");
# 56 [ + + ]: 1630 : if (!m_fileout) {
# 57 : 2 : return false;
# 58 : 2 : }
# 59 : :
# 60 : 1628 : setbuf(m_fileout, nullptr); // unbuffered
# 61 : :
# 62 : : // Add newlines to the logfile to distinguish this execution from the
# 63 : : // last one.
# 64 : 1628 : FileWriteStr("\n\n\n\n\n", m_fileout);
# 65 : 1628 : }
# 66 : :
# 67 : : // dump buffered messages from before we opened the log
# 68 : 1629 : m_buffering = false;
# 69 [ + + ]: 10690 : while (!m_msgs_before_open.empty()) {
# 70 : 9061 : const std::string& s = m_msgs_before_open.front();
# 71 : :
# 72 [ + + ]: 9061 : if (m_print_to_file) FileWriteStr(s, m_fileout);
# 73 [ - + ]: 9061 : if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
# 74 [ + + ]: 9061 : for (const auto& cb : m_print_callbacks) {
# 75 : 3438 : cb(s);
# 76 : 3438 : }
# 77 : :
# 78 : 9061 : m_msgs_before_open.pop_front();
# 79 : 9061 : }
# 80 [ - + ]: 1629 : if (m_print_to_console) fflush(stdout);
# 81 : :
# 82 : 1629 : return true;
# 83 : 1631 : }
# 84 : :
# 85 : : void BCLog::Logger::DisconnectTestLogger()
# 86 : 837 : {
# 87 : 837 : StdLockGuard scoped_lock(m_cs);
# 88 : 837 : m_buffering = true;
# 89 [ + - ]: 837 : if (m_fileout != nullptr) fclose(m_fileout);
# 90 : 837 : m_fileout = nullptr;
# 91 : 837 : m_print_callbacks.clear();
# 92 : 837 : }
# 93 : :
# 94 : : void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
# 95 : 1636 : {
# 96 : 1636 : m_categories |= flag;
# 97 : 1636 : }
# 98 : :
# 99 : : bool BCLog::Logger::EnableCategory(const std::string& str)
# 100 : 1636 : {
# 101 : 1636 : BCLog::LogFlags flag;
# 102 [ - + ]: 1636 : if (!GetLogCategory(flag, str)) return false;
# 103 : 1636 : EnableCategory(flag);
# 104 : 1636 : return true;
# 105 : 1636 : }
# 106 : :
# 107 : : void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
# 108 : 3271 : {
# 109 : 3271 : m_categories &= ~flag;
# 110 : 3271 : }
# 111 : :
# 112 : : bool BCLog::Logger::DisableCategory(const std::string& str)
# 113 : 3271 : {
# 114 : 3271 : BCLog::LogFlags flag;
# 115 [ - + ]: 3271 : if (!GetLogCategory(flag, str)) return false;
# 116 : 3271 : DisableCategory(flag);
# 117 : 3271 : return true;
# 118 : 3271 : }
# 119 : :
# 120 : : bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
# 121 : 2510372 : {
# 122 : 2510372 : return (m_categories.load(std::memory_order_relaxed) & category) != 0;
# 123 : 2510372 : }
# 124 : :
# 125 : : bool BCLog::Logger::DefaultShrinkDebugFile() const
# 126 : 793 : {
# 127 : 793 : return m_categories == BCLog::NONE;
# 128 : 793 : }
# 129 : :
# 130 : : struct CLogCategoryDesc {
# 131 : : BCLog::LogFlags flag;
# 132 : : std::string category;
# 133 : : };
# 134 : :
# 135 : : const CLogCategoryDesc LogCategories[] =
# 136 : : {
# 137 : : {BCLog::NONE, "0"},
# 138 : : {BCLog::NONE, "none"},
# 139 : : {BCLog::NET, "net"},
# 140 : : {BCLog::TOR, "tor"},
# 141 : : {BCLog::MEMPOOL, "mempool"},
# 142 : : {BCLog::HTTP, "http"},
# 143 : : {BCLog::BENCH, "bench"},
# 144 : : {BCLog::ZMQ, "zmq"},
# 145 : : {BCLog::WALLETDB, "walletdb"},
# 146 : : {BCLog::RPC, "rpc"},
# 147 : : {BCLog::ESTIMATEFEE, "estimatefee"},
# 148 : : {BCLog::ADDRMAN, "addrman"},
# 149 : : {BCLog::SELECTCOINS, "selectcoins"},
# 150 : : {BCLog::REINDEX, "reindex"},
# 151 : : {BCLog::CMPCTBLOCK, "cmpctblock"},
# 152 : : {BCLog::RAND, "rand"},
# 153 : : {BCLog::PRUNE, "prune"},
# 154 : : {BCLog::PROXY, "proxy"},
# 155 : : {BCLog::MEMPOOLREJ, "mempoolrej"},
# 156 : : {BCLog::LIBEVENT, "libevent"},
# 157 : : {BCLog::COINDB, "coindb"},
# 158 : : {BCLog::QT, "qt"},
# 159 : : {BCLog::LEVELDB, "leveldb"},
# 160 : : {BCLog::VALIDATION, "validation"},
# 161 : : {BCLog::I2P, "i2p"},
# 162 : : {BCLog::IPC, "ipc"},
# 163 : : #ifdef DEBUG_LOCKCONTENTION
# 164 : : {BCLog::LOCK, "lock"},
# 165 : : #endif
# 166 : : {BCLog::UTIL, "util"},
# 167 : : {BCLog::BLOCKSTORE, "blockstorage"},
# 168 : : {BCLog::ALL, "1"},
# 169 : : {BCLog::ALL, "all"},
# 170 : : };
# 171 : :
# 172 : : bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
# 173 : 4907 : {
# 174 [ + + ]: 4907 : if (str == "") {
# 175 : 1635 : flag = BCLog::ALL;
# 176 : 1635 : return true;
# 177 : 1635 : }
# 178 [ + - ]: 70349 : for (const CLogCategoryDesc& category_desc : LogCategories) {
# 179 [ + + ]: 70349 : if (category_desc.category == str) {
# 180 : 3272 : flag = category_desc.flag;
# 181 : 3272 : return true;
# 182 : 3272 : }
# 183 : 70349 : }
# 184 : 0 : return false;
# 185 : 3272 : }
# 186 : :
# 187 : : std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
# 188 : 3271 : {
# 189 : : // Sort log categories by alphabetical order.
# 190 : 3271 : std::array<CLogCategoryDesc, std::size(LogCategories)> categories;
# 191 : 3271 : std::copy(std::begin(LogCategories), std::end(LogCategories), categories.begin());
# 192 : 520089 : std::sort(categories.begin(), categories.end(), [](auto a, auto b) { return a.category < b.category; });
# 193 : :
# 194 : 3271 : std::vector<LogCategory> ret;
# 195 [ + + ]: 98130 : for (const CLogCategoryDesc& category_desc : categories) {
# 196 [ + + ][ + + ]: 98130 : if (category_desc.flag == BCLog::NONE || category_desc.flag == BCLog::ALL) continue;
# 197 : 85046 : LogCategory catActive;
# 198 : 85046 : catActive.category = category_desc.category;
# 199 : 85046 : catActive.active = WillLogCategory(category_desc.flag);
# 200 : 85046 : ret.push_back(catActive);
# 201 : 85046 : }
# 202 : 3271 : return ret;
# 203 : 3271 : }
# 204 : :
# 205 : : std::string BCLog::Logger::LogTimestampStr(const std::string& str)
# 206 : 2748758 : {
# 207 : 2748758 : std::string strStamped;
# 208 : :
# 209 [ - + ]: 2748758 : if (!m_log_timestamps)
# 210 : 0 : return str;
# 211 : :
# 212 [ + + ]: 2748758 : if (m_started_new_line) {
# 213 : 2746104 : int64_t nTimeMicros = GetTimeMicros();
# 214 : 2746104 : strStamped = FormatISO8601DateTime(nTimeMicros/1000000);
# 215 [ + + ]: 2746104 : if (m_log_time_micros) {
# 216 : 2723689 : strStamped.pop_back();
# 217 : 2723689 : strStamped += strprintf(".%06dZ", nTimeMicros%1000000);
# 218 : 2723689 : }
# 219 : 2746104 : std::chrono::seconds mocktime = GetMockTime();
# 220 [ + + ]: 2746104 : if (mocktime > 0s) {
# 221 : 354037 : strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
# 222 : 354037 : }
# 223 : 2746104 : strStamped += ' ' + str;
# 224 : 2746104 : } else
# 225 : 2654 : strStamped = str;
# 226 : :
# 227 : 2748758 : return strStamped;
# 228 : 2748758 : }
# 229 : :
# 230 : : namespace BCLog {
# 231 : : /** Belts and suspenders: make sure outgoing log messages don't contain
# 232 : : * potentially suspicious characters, such as terminal control codes.
# 233 : : *
# 234 : : * This escapes control characters except newline ('\n') in C syntax.
# 235 : : * It escapes instead of removes them to still allow for troubleshooting
# 236 : : * issues where they accidentally end up in strings.
# 237 : : */
# 238 : 2748762 : std::string LogEscapeMessage(const std::string& str) {
# 239 : 2748762 : std::string ret;
# 240 [ + + ]: 218459898 : for (char ch_in : str) {
# 241 : 218459898 : uint8_t ch = (uint8_t)ch_in;
# 242 [ + + ][ + + ]: 218459898 : if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
# [ + + ]
# 243 : 218458344 : ret += ch_in;
# 244 : 218458344 : } else {
# 245 : 1554 : ret += strprintf("\\x%02x", ch);
# 246 : 1554 : }
# 247 : 218459898 : }
# 248 : 2748762 : return ret;
# 249 : 2748762 : }
# 250 : : } // namespace BCLog
# 251 : :
# 252 : : void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line)
# 253 : 2748587 : {
# 254 : 2748587 : StdLockGuard scoped_lock(m_cs);
# 255 : 2748587 : std::string str_prefixed = LogEscapeMessage(str);
# 256 : :
# 257 [ + + ][ + + ]: 2748587 : if (m_log_sourcelocations && m_started_new_line) {
# 258 : 2723689 : str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
# 259 : 2723689 : }
# 260 : :
# 261 [ - + ][ # # ]: 2748587 : if (m_log_threadnames && m_started_new_line) {
# 262 : 0 : str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
# 263 : 0 : }
# 264 : :
# 265 : 2748587 : str_prefixed = LogTimestampStr(str_prefixed);
# 266 : :
# 267 [ + + ][ + + ]: 2748758 : m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
# 268 : :
# 269 [ + + ]: 2748587 : if (m_buffering) {
# 270 : : // buffer if we haven't started logging yet
# 271 : 31515 : m_msgs_before_open.push_back(str_prefixed);
# 272 : 31515 : return;
# 273 : 31515 : }
# 274 : :
# 275 [ - + ]: 2717072 : if (m_print_to_console) {
# 276 : : // print to console
# 277 : 0 : fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
# 278 : 0 : fflush(stdout);
# 279 : 0 : }
# 280 [ + + ]: 2717072 : for (const auto& cb : m_print_callbacks) {
# 281 : 210742 : cb(str_prefixed);
# 282 : 210742 : }
# 283 [ + + ]: 2717243 : if (m_print_to_file) {
# 284 : 2717243 : assert(m_fileout != nullptr);
# 285 : :
# 286 : : // reopen the log file, if requested
# 287 [ - + ]: 2717243 : if (m_reopen_file) {
# 288 : 0 : m_reopen_file = false;
# 289 : 0 : FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
# 290 [ # # ]: 0 : if (new_fileout) {
# 291 : 0 : setbuf(new_fileout, nullptr); // unbuffered
# 292 : 0 : fclose(m_fileout);
# 293 : 0 : m_fileout = new_fileout;
# 294 : 0 : }
# 295 : 0 : }
# 296 : 2717243 : FileWriteStr(str_prefixed, m_fileout);
# 297 : 2717243 : }
# 298 : 2717072 : }
# 299 : :
# 300 : : void BCLog::Logger::ShrinkDebugFile()
# 301 : 0 : {
# 302 : : // Amount of debug.log to save at end when shrinking (must fit in memory)
# 303 : 0 : constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
# 304 : :
# 305 : 0 : assert(!m_file_path.empty());
# 306 : :
# 307 : : // Scroll debug.log if it's getting too big
# 308 : 0 : FILE* file = fsbridge::fopen(m_file_path, "r");
# 309 : :
# 310 : : // Special files (e.g. device nodes) may not have a size.
# 311 : 0 : size_t log_size = 0;
# 312 : 0 : try {
# 313 : 0 : log_size = fs::file_size(m_file_path);
# 314 : 0 : } catch (const fs::filesystem_error&) {}
# 315 : :
# 316 : : // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
# 317 : : // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
# 318 [ # # ][ # # ]: 0 : if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
# 319 : 0 : {
# 320 : : // Restart the file with some of the end
# 321 : 0 : std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
# 322 [ # # ]: 0 : if (fseek(file, -((long)vch.size()), SEEK_END)) {
# 323 : 0 : LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
# 324 : 0 : fclose(file);
# 325 : 0 : return;
# 326 : 0 : }
# 327 : 0 : int nBytes = fread(vch.data(), 1, vch.size(), file);
# 328 : 0 : fclose(file);
# 329 : :
# 330 : 0 : file = fsbridge::fopen(m_file_path, "w");
# 331 [ # # ]: 0 : if (file)
# 332 : 0 : {
# 333 : 0 : fwrite(vch.data(), 1, nBytes, file);
# 334 : 0 : fclose(file);
# 335 : 0 : }
# 336 : 0 : }
# 337 [ # # ]: 0 : else if (file != nullptr)
# 338 : 0 : fclose(file);
# 339 : 0 : }
|
