logging.h raw
1 // Copyright (c) 2009-2010 Satoshi Nakamoto
2 // Copyright (c) 2009-present The Limenka 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 LIMENKA_LOGGING_H
7 #define LIMENKA_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 ALL = ~NONE,
98 };
99 enum class Level {
100 Trace = 0, // High-volume or detailed logging for development/debugging
101 Debug, // Reasonably noisy logging, but still usable in production
102 Info, // Default
103 Warning,
104 Error,
105 };
106 constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
107 constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
108 constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW
109 constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset
110 constexpr bool DEFAULT_LOGRATELIMIT{true};
111
112 //! Fixed window rate limiter for logging.
113 class LogRateLimiter
114 {
115 public:
116 //! Keeps track of an individual source location and how many available bytes are left for logging from it.
117 struct Stats {
118 //! Remaining bytes
119 uint64_t m_available_bytes;
120 //! Number of bytes that were consumed but didn't fit in the available bytes.
121 uint64_t m_dropped_bytes{0};
122
123 Stats(uint64_t max_bytes) : m_available_bytes{max_bytes} {}
124 //! Updates internal accounting and returns true if enough available_bytes were remaining
125 bool Consume(uint64_t bytes);
126 };
127
128 private:
129 mutable StdMutex m_mutex;
130
131 //! Stats for each source location that has attempted to log something.
132 std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
133 //! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
134 std::atomic<bool> m_suppression_active{false};
135 LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
136
137 public:
138 using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>;
139 /**
140 * @param scheduler_func Callable object used to schedule resetting the window. The first
141 * parameter is the function to be executed, and the second is the
142 * reset_window interval.
143 * @param max_bytes Maximum number of bytes that can be logged for each source
144 * location.
145 * @param reset_window Time window after which the stats are reset.
146 */
147 static std::shared_ptr<LogRateLimiter> Create(
148 SchedulerFunction&& scheduler_func,
149 uint64_t max_bytes,
150 std::chrono::seconds reset_window);
151 //! Maximum number of bytes logged per location per window.
152 const uint64_t m_max_bytes;
153 //! Interval after which the window is reset.
154 const std::chrono::seconds m_reset_window;
155 //! Suppression status of a source log location.
156 enum class Status {
157 UNSUPPRESSED, // string fits within the limit
158 NEWLY_SUPPRESSED, // suppression has started since this string
159 STILL_SUPPRESSED, // suppression is still ongoing
160 };
161 //! Consumes `source_loc`'s available bytes corresponding to the size of the (formatted)
162 //! `str` and returns its status.
163 [[nodiscard]] Status Consume(
164 const std::source_location& source_loc,
165 const std::string& str) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
166 //! Resets all usage to zero. Called periodically by the scheduler.
167 void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
168 //! Returns true if any log locations are currently being suppressed.
169 bool SuppressionsActive() const { return m_suppression_active; }
170 };
171
172 class Logger
173 {
174 public:
175 struct BufferedLog {
176 SystemClock::time_point now;
177 std::chrono::seconds mocktime;
178 std::string str, threadname;
179 std::source_location source_loc;
180 LogFlags category;
181 Level level;
182 };
183
184 private:
185 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
186
187 FILE* m_fileout GUARDED_BY(m_cs) = nullptr;
188 std::list<BufferedLog> m_msgs_before_open GUARDED_BY(m_cs);
189 bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started.
190 size_t m_max_buffer_memusage GUARDED_BY(m_cs){DEFAULT_MAX_LOG_BUFFER};
191 size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0};
192 size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
193
194 //! Manages the rate limiting of each log location.
195 std::shared_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
196
197 //! Category-specific log level. Overrides `m_log_level`.
198 std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
199
200 //! If there is no category-specific log level, all logs with a severity
201 //! level lower than `m_log_level` will be ignored.
202 std::atomic<Level> m_log_level{DEFAULT_LOG_LEVEL};
203
204 /** Log categories bitfield. */
205 std::atomic<CategoryMask> m_categories{BCLog::NONE};
206
207 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;
208
209 std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const;
210
211 /** Slots that connect to the print signal */
212 std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {};
213
214 /** Send a string to the log output (internal) */
215 void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
216 EXCLUSIVE_LOCKS_REQUIRED(m_cs);
217
218 std::string GetLogPrefix(LogFlags category, Level level) const;
219
220 public:
221 bool m_print_to_console = false;
222 bool m_print_to_file = false;
223
224 bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS;
225 bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
226 bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
227 bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS;
228 bool m_always_print_category_level = DEFAULT_LOGLEVELALWAYS;
229
230 fs::path m_file_path;
231 std::atomic<bool> m_reopen_file{false};
232
233 /** Send a string to the log output */
234 void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
235 EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
236
237 /** Returns whether logs will be written to any output */
238 bool Enabled() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
239 {
240 StdLockGuard scoped_lock(m_cs);
241 return m_buffering || m_print_to_console || m_print_to_file || !m_print_callbacks.empty();
242 }
243
244 /** Connect a slot to the print signal and return the connection */
245 std::list<std::function<void(const std::string&)>>::iterator PushBackCallback(std::function<void(const std::string&)> fun) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
246 {
247 StdLockGuard scoped_lock(m_cs);
248 m_print_callbacks.push_back(std::move(fun));
249 return --m_print_callbacks.end();
250 }
251
252 /** Delete a connection */
253 void DeleteCallback(std::list<std::function<void(const std::string&)>>::iterator it) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
254 {
255 StdLockGuard scoped_lock(m_cs);
256 m_print_callbacks.erase(it);
257 }
258
259 /** Start logging (and flush all buffered messages) */
260 bool StartLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
261 /** Only for testing */
262 void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
263
264 void SetRateLimiting(std::shared_ptr<LogRateLimiter> limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
265 {
266 StdLockGuard scoped_lock(m_cs);
267 m_limiter = std::move(limiter);
268 }
269
270 /** Disable logging
271 * This offers a slight speedup and slightly smaller memory usage
272 * compared to leaving the logging system in its default state.
273 * Mostly intended for liblimenka-kernel apps that don't want any logging.
274 * Should be used instead of StartLogging().
275 */
276 void DisableLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
277
278 void ShrinkDebugFile();
279
280 std::unordered_map<LogFlags, Level> CategoryLevels() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
281 {
282 StdLockGuard scoped_lock(m_cs);
283 return m_category_log_levels;
284 }
285 void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
286 {
287 StdLockGuard scoped_lock(m_cs);
288 m_category_log_levels = levels;
289 }
290 bool SetCategoryLogLevel(std::string_view category_str, std::string_view level_str) EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
291
292 Level LogLevel() const { return m_log_level.load(); }
293 void SetLogLevel(Level level) { m_log_level = level; }
294 bool SetLogLevel(std::string_view level);
295
296 CategoryMask GetCategoryMask() const { return m_categories.load(); }
297
298 void EnableCategory(LogFlags flag);
299 bool EnableCategory(std::string_view str);
300 void DisableCategory(LogFlags flag);
301 bool DisableCategory(std::string_view str);
302
303 bool WillLogCategory(LogFlags category) const;
304 bool WillLogCategoryLevel(LogFlags category, Level level) const EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
305
306 /** Returns a vector of the log categories in alphabetical order. */
307 std::vector<LogCategory> LogCategoriesList() const;
308 /** Returns a string with the log categories in alphabetical order. */
309 std::string LogCategoriesString() const
310 {
311 return util::Join(LogCategoriesList(), ", ", [&](const LogCategory& i) { return i.category; });
312 };
313
314 //! Returns a string with all user-selectable log levels.
315 std::string LogLevelsString() const;
316
317 //! Returns the string representation of a log level.
318 static std::string LogLevelToStr(BCLog::Level level);
319
320 bool DefaultShrinkDebugFile() const;
321 };
322
323 } // namespace BCLog
324
325 BCLog::Logger& LogInstance();
326
327 /** Return true if log accepts specified category, at the specified level. */
328 static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level)
329 {
330 return LogInstance().WillLogCategoryLevel(category, level);
331 }
332
333 /** Return true if str parses as a log category and set the flag */
334 bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str);
335
336 template <typename... Args>
337 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)
338 {
339 if (LogInstance().Enabled()) {
340 std::string log_msg;
341 try {
342 log_msg = tfm::format(fmt, args...);
343 } catch (tinyformat::format_error& fmterr) {
344 log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt;
345 }
346 LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level, should_ratelimit);
347 }
348 }
349
350 #define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__)
351
352 // Log unconditionally. Uses basic rate limiting to mitigate disk filling attacks.
353 // Be conservative when using functions that unconditionally log to debug.log!
354 // It should not be the case that an inbound peer can fill up a user's storage
355 // with debug.log entries.
356 #define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/true, __VA_ARGS__)
357 #define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, /*should_ratelimit=*/true, __VA_ARGS__)
358 #define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, /*should_ratelimit=*/true, __VA_ARGS__)
359
360 // Deprecated unconditional logging.
361 #define LogPrintf(...) LogInfo(__VA_ARGS__)
362
363 // Use a macro instead of a function for conditional logging to prevent
364 // evaluating arguments when logging for the category is not enabled.
365
366 // Log by prefixing the output with the passed category name and severity level. This can either
367 // log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info
368 // is passed. If this function logs unconditionally, logging to disk is rate-limited. This is
369 // important so that callers don't need to worry about accidentally introducing a disk-fill
370 // vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be
371 // developers or power users who are aware that -debug may cause excessive disk usage due to logging.
372 #define LogPrintLevel(category, level, ...) \
373 do { \
374 if (LogAcceptCategory((category), (level))) { \
375 bool rate_limit{level >= BCLog::Level::Info}; \
376 LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \
377 } \
378 } while (0)
379
380 // Log conditionally, prefixing the output with the passed category name.
381 #define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__)
382 #define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__)
383
384 #endif // LIMENKA_LOGGING_H
385