logging.h
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 #ifndef BITCOIN_LOGGING_H 7 #define BITCOIN_LOGGING_H 8 9 #include <crypto/siphash.h> 10 #include <threadsafety.h> 11 #include <tinyformat.h> 12 #include <util/fs.h> 13 #include <util/string.h> 14 #include <util/time.h> 15 16 #include <atomic> 17 #include <cstdint> 18 #include <cstring> 19 #include <functional> 20 #include <list> 21 #include <memory> 22 #include <mutex> 23 #include <source_location> 24 #include <string> 25 #include <unordered_map> 26 #include <unordered_set> 27 #include <vector> 28 29 static const bool DEFAULT_LOGTIMEMICROS = false; 30 static const bool DEFAULT_LOGIPS = false; 31 static const bool DEFAULT_LOGTIMESTAMPS = true; 32 static const bool DEFAULT_LOGTHREADNAMES = false; 33 static const bool DEFAULT_LOGSOURCELOCATIONS = false; 34 static constexpr bool DEFAULT_LOGLEVELALWAYS = false; 35 extern const char * const DEFAULT_DEBUGLOGFILE; 36 37 extern bool fLogIPs; 38 39 struct SourceLocationEqual { 40 bool operator()(const std::source_location& lhs, const std::source_location& rhs) const noexcept 41 { 42 return lhs.line() == rhs.line() && std::string_view(lhs.file_name()) == std::string_view(rhs.file_name()); 43 } 44 }; 45 46 struct SourceLocationHasher { 47 size_t operator()(const std::source_location& s) const noexcept 48 { 49 // Use CSipHasher(0, 0) as a simple way to get uniform distribution. 50 return size_t(CSipHasher(0, 0) 51 .Write(s.line()) 52 .Write(MakeUCharSpan(std::string_view{s.file_name()})) 53 .Finalize()); 54 } 55 }; 56 57 struct LogCategory { 58 std::string category; 59 bool active; 60 }; 61 62 namespace BCLog { 63 using CategoryMask = uint64_t; 64 enum LogFlags : CategoryMask { 65 NONE = CategoryMask{0}, 66 NET = (CategoryMask{1} << 0), 67 TOR = (CategoryMask{1} << 1), 68 MEMPOOL = (CategoryMask{1} << 2), 69 HTTP = (CategoryMask{1} << 3), 70 BENCH = (CategoryMask{1} << 4), 71 ZMQ = (CategoryMask{1} << 5), 72 WALLETDB = (CategoryMask{1} << 6), 73 RPC = (CategoryMask{1} << 7), 74 ESTIMATEFEE = (CategoryMask{1} << 8), 75 ADDRMAN = (CategoryMask{1} << 9), 76 SELECTCOINS = (CategoryMask{1} << 10), 77 REINDEX = (CategoryMask{1} << 11), 78 CMPCTBLOCK = (CategoryMask{1} << 12), 79 RAND = (CategoryMask{1} << 13), 80 PRUNE = (CategoryMask{1} << 14), 81 PROXY = (CategoryMask{1} << 15), 82 MEMPOOLREJ = (CategoryMask{1} << 16), 83 LIBEVENT = (CategoryMask{1} << 17), 84 COINDB = (CategoryMask{1} << 18), 85 QT = (CategoryMask{1} << 19), 86 LEVELDB = (CategoryMask{1} << 20), 87 VALIDATION = (CategoryMask{1} << 21), 88 I2P = (CategoryMask{1} << 22), 89 IPC = (CategoryMask{1} << 23), 90 #ifdef DEBUG_LOCKCONTENTION 91 LOCK = (CategoryMask{1} << 24), 92 #endif 93 BLOCKSTORAGE = (CategoryMask{1} << 25), 94 TXRECONCILIATION = (CategoryMask{1} << 26), 95 SCAN = (CategoryMask{1} << 27), 96 TXPACKAGES = (CategoryMask{1} << 28), 97 KERNEL = (CategoryMask{1} << 29), 98 ALL = ~NONE, 99 }; 100 enum class Level { 101 Trace = 0, // High-volume or detailed logging for development/debugging 102 Debug, // Reasonably noisy logging, but still usable in production 103 Info, // Default 104 Warning, 105 Error, 106 }; 107 constexpr auto DEFAULT_LOG_LEVEL{Level::Debug}; 108 constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging 109 constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW 110 constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset 111 constexpr bool DEFAULT_LOGRATELIMIT{true}; 112 113 //! Fixed window rate limiter for logging. 114 class LogRateLimiter 115 { 116 public: 117 //! Keeps track of an individual source location and how many available bytes are left for logging from it. 118 struct Stats { 119 //! Remaining bytes 120 uint64_t m_available_bytes; 121 //! Number of bytes that were consumed but didn't fit in the available bytes. 122 uint64_t m_dropped_bytes{0}; 123 124 Stats(uint64_t max_bytes) : m_available_bytes{max_bytes} {} 125 //! Updates internal accounting and returns true if enough available_bytes were remaining 126 bool Consume(uint64_t bytes); 127 }; 128 129 private: 130 mutable StdMutex m_mutex; 131 132 //! Stats for each source location that has attempted to log something. 133 std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex); 134 //! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons. 135 std::atomic<bool> m_suppression_active{false}; 136 LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window); 137 138 public: 139 using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>; 140 /** 141 * @param scheduler_func Callable object used to schedule resetting the window. The first 142 * parameter is the function to be executed, and the second is the 143 * reset_window interval. 144 * @param max_bytes Maximum number of bytes that can be logged for each source 145 * location. 146 * @param reset_window Time window after which the stats are reset. 147 */ 148 static std::shared_ptr<LogRateLimiter> Create( 149 SchedulerFunction&& scheduler_func, 150 uint64_t max_bytes, 151 std::chrono::seconds reset_window); 152 //! Maximum number of bytes logged per location per window. 153 const uint64_t m_max_bytes; 154 //! Interval after which the window is reset. 155 const std::chrono::seconds m_reset_window; 156 //! Suppression status of a source log location. 157 enum class Status { 158 UNSUPPRESSED, // string fits within the limit 159 NEWLY_SUPPRESSED, // suppression has started since this string 160 STILL_SUPPRESSED, // suppression is still ongoing 161 }; 162 //! Consumes `source_loc`'s available bytes corresponding to the size of the (formatted) 163 //! `str` and returns its status. 164 [[nodiscard]] Status Consume( 165 const std::source_location& source_loc, 166 const std::string& str) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex); 167 //! Resets all usage to zero. Called periodically by the scheduler. 168 void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex); 169 //! Returns true if any log locations are currently being suppressed. 170 bool SuppressionsActive() const { return m_suppression_active; } 171 }; 172 173 class Logger 174 { 175 public: 176 struct BufferedLog { 177 SystemClock::time_point now; 178 std::chrono::seconds mocktime; 179 std::string str, threadname; 180 std::source_location source_loc; 181 LogFlags category; 182 Level level; 183 }; 184 185 private: 186 mutable StdMutex m_cs; // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected 187 188 FILE* m_fileout GUARDED_BY(m_cs) = nullptr; 189 std::list<BufferedLog> m_msgs_before_open GUARDED_BY(m_cs); 190 bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started. 191 size_t m_max_buffer_memusage GUARDED_BY(m_cs){DEFAULT_MAX_LOG_BUFFER}; 192 size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0}; 193 size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0}; 194 195 //! Manages the rate limiting of each log location. 196 std::shared_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs); 197 198 //! Category-specific log level. Overrides `m_log_level`. 199 std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs); 200 201 //! If there is no category-specific log level, all logs with a severity 202 //! level lower than `m_log_level` will be ignored. 203 std::atomic<Level> m_log_level{DEFAULT_LOG_LEVEL}; 204 205 /** Log categories bitfield. */ 206 std::atomic<CategoryMask> m_categories{BCLog::NONE}; 207 208 void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const std::source_location& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const; 209 210 std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const; 211 212 /** Slots that connect to the print signal */ 213 std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {}; 214 215 /** Send a string to the log output (internal) */ 216 void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) 217 EXCLUSIVE_LOCKS_REQUIRED(m_cs); 218 219 std::string GetLogPrefix(LogFlags category, Level level) const; 220 221 public: 222 bool m_print_to_console = false; 223 bool m_print_to_file = false; 224 225 bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS; 226 bool m_log_time_micros = DEFAULT_LOGTIMEMICROS; 227 bool m_log_threadnames = DEFAULT_LOGTHREADNAMES; 228 bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS; 229 bool m_always_print_category_level = DEFAULT_LOGLEVELALWAYS; 230 231 fs::path m_file_path; 232 std::atomic<bool> m_reopen_file{false}; 233 234 /** Send a string to the log output */ 235 void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) 236 EXCLUSIVE_LOCKS_REQUIRED(!m_cs); 237 238 /** Returns whether logs will be written to any output */ 239 bool Enabled() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs) 240 { 241 StdLockGuard scoped_lock(m_cs); 242 return m_buffering || m_print_to_console || m_print_to_file || !m_print_callbacks.empty(); 243 } 244 245 /** Connect a slot to the print signal and return the connection */ 246 std::list<std::function<void(const std::string&)>>::iterator PushBackCallback(std::function<void(const std::string&)> fun) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) 247 { 248 StdLockGuard scoped_lock(m_cs); 249 m_print_callbacks.push_back(std::move(fun)); 250 return --m_print_callbacks.end(); 251 } 252 253 /** Delete a connection */ 254 void DeleteCallback(std::list<std::function<void(const std::string&)>>::iterator it) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) 255 { 256 StdLockGuard scoped_lock(m_cs); 257 m_print_callbacks.erase(it); 258 } 259 260 size_t NumConnections() 261 { 262 StdLockGuard scoped_lock(m_cs); 263 return m_print_callbacks.size(); 264 } 265 266 /** Start logging (and flush all buffered messages) */ 267 bool StartLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); 268 /** Only for testing */ 269 void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); 270 271 void SetRateLimiting(std::shared_ptr<LogRateLimiter> limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) 272 { 273 StdLockGuard scoped_lock(m_cs); 274 m_limiter = std::move(limiter); 275 } 276 277 /** Disable logging 278 * This offers a slight speedup and slightly smaller memory usage 279 * compared to leaving the logging system in its default state. 280 * Mostly intended for libbitcoin-kernel apps that don't want any logging. 281 * Should be used instead of StartLogging(). 282 */ 283 void DisableLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs); 284 285 void ShrinkDebugFile(); 286 287 std::unordered_map<LogFlags, Level> CategoryLevels() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs) 288 { 289 StdLockGuard scoped_lock(m_cs); 290 return m_category_log_levels; 291 } 292 void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels) EXCLUSIVE_LOCKS_REQUIRED(!m_cs) 293 { 294 StdLockGuard scoped_lock(m_cs); 295 m_category_log_levels = levels; 296 } 297 void AddCategoryLogLevel(LogFlags category, Level level) 298 { 299 StdLockGuard scoped_lock(m_cs); 300 m_category_log_levels[category] = level; 301 } 302 bool SetCategoryLogLevel(std::string_view category_str, std::string_view level_str) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); 303 304 Level LogLevel() const { return m_log_level.load(); } 305 void SetLogLevel(Level level) { m_log_level = level; } 306 bool SetLogLevel(std::string_view level); 307 308 CategoryMask GetCategoryMask() const { return m_categories.load(); } 309 310 void EnableCategory(LogFlags flag); 311 bool EnableCategory(std::string_view str); 312 void DisableCategory(LogFlags flag); 313 bool DisableCategory(std::string_view str); 314 315 bool WillLogCategory(LogFlags category) const; 316 bool WillLogCategoryLevel(LogFlags category, Level level) const EXCLUSIVE_LOCKS_REQUIRED(!m_cs); 317 318 /** Returns a vector of the log categories in alphabetical order. */ 319 std::vector<LogCategory> LogCategoriesList() const; 320 /** Returns a string with the log categories in alphabetical order. */ 321 std::string LogCategoriesString() const 322 { 323 return util::Join(LogCategoriesList(), ", ", [&](const LogCategory& i) { return i.category; }); 324 }; 325 326 //! Returns a string with all user-selectable log levels. 327 std::string LogLevelsString() const; 328 329 //! Returns the string representation of a log level. 330 static std::string LogLevelToStr(BCLog::Level level); 331 332 bool DefaultShrinkDebugFile() const; 333 }; 334 335 } // namespace BCLog 336 337 BCLog::Logger& LogInstance(); 338 339 /** Return true if log accepts specified category, at the specified level. */ 340 static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level) 341 { 342 return LogInstance().WillLogCategoryLevel(category, level); 343 } 344 345 /** Return true if str parses as a log category and set the flag */ 346 bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); 347 348 template <typename... Args> 349 inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args) 350 { 351 if (LogInstance().Enabled()) { 352 std::string log_msg; 353 try { 354 log_msg = tfm::format(fmt, args...); 355 } catch (tinyformat::format_error& fmterr) { 356 log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt; 357 } 358 LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level, should_ratelimit); 359 } 360 } 361 362 #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__) 363 364 // Log unconditionally. Uses basic rate limiting to mitigate disk filling attacks. 365 // Be conservative when using functions that unconditionally log to debug.log! 366 // It should not be the case that an inbound peer can fill up a user's storage 367 // with debug.log entries. 368 #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/true, __VA_ARGS__) 369 #define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, /*should_ratelimit=*/true, __VA_ARGS__) 370 #define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, /*should_ratelimit=*/true, __VA_ARGS__) 371 372 // Deprecated unconditional logging. 373 #define LogPrintf(...) LogInfo(__VA_ARGS__) 374 375 // Use a macro instead of a function for conditional logging to prevent 376 // evaluating arguments when logging for the category is not enabled. 377 378 // Log by prefixing the output with the passed category name and severity level. This can either 379 // log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info 380 // is passed. If this function logs unconditionally, logging to disk is rate-limited. This is 381 // important so that callers don't need to worry about accidentally introducing a disk-fill 382 // vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be 383 // developers or power users who are aware that -debug may cause excessive disk usage due to logging. 384 #define LogPrintLevel(category, level, ...) \ 385 do { \ 386 if (LogAcceptCategory((category), (level))) { \ 387 bool rate_limit{level >= BCLog::Level::Info}; \ 388 LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \ 389 } \ 390 } while (0) 391 392 // Log conditionally, prefixing the output with the passed category name. 393 #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) 394 #define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__) 395 396 #endif // BITCOIN_LOGGING_H