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