/src/brpc/src/butil/logging.cc
Line | Count | Source (jump to first uncovered line) |
1 | | // Licensed to the Apache Software Foundation (ASF) under one |
2 | | // or more contributor license agreements. See the NOTICE file |
3 | | // distributed with this work for additional information |
4 | | // regarding copyright ownership. The ASF licenses this file |
5 | | // to you under the Apache License, Version 2.0 (the |
6 | | // "License"); you may not use this file except in compliance |
7 | | // with the License. You may obtain a copy of the License at |
8 | | // |
9 | | // http://www.apache.org/licenses/LICENSE-2.0 |
10 | | // |
11 | | // Unless required by applicable law or agreed to in writing, |
12 | | // software distributed under the License is distributed on an |
13 | | // "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY |
14 | | // KIND, either express or implied. See the License for the |
15 | | // specific language governing permissions and limitations |
16 | | // under the License. |
17 | | |
18 | | // Date: 2012-10-08 23:53:50 |
19 | | |
20 | | #include "butil/logging.h" |
21 | | |
22 | | #include <gflags/gflags.h> |
23 | | DEFINE_bool(log_as_json, false, "Print log as a valid JSON"); |
24 | | DEFINE_bool(escape_log, false, "Escape log content before printing"); |
25 | | |
26 | | #if !BRPC_WITH_GLOG |
27 | | |
28 | | #if defined(OS_WIN) |
29 | | #include <io.h> |
30 | | #include <windows.h> |
31 | | typedef HANDLE FileHandle; |
32 | | typedef HANDLE MutexHandle; |
33 | | // Windows warns on using write(). It prefers _write(). |
34 | | #define write(fd, buf, count) _write(fd, buf, static_cast<unsigned int>(count)) |
35 | | // Windows doesn't define STDERR_FILENO. Define it here. |
36 | | #define STDERR_FILENO 2 |
37 | | #elif defined(OS_MACOSX) |
38 | | #include <mach/mach.h> |
39 | | #include <mach/mach_time.h> |
40 | | #include <mach-o/dyld.h> |
41 | | #elif defined(OS_POSIX) |
42 | | #if defined(OS_NACL) || defined(OS_LINUX) |
43 | | #include <sys/time.h> // timespec doesn't seem to be in <time.h> |
44 | | #else |
45 | | #include <sys/syscall.h> |
46 | | #endif |
47 | | #include <time.h> |
48 | | #endif |
49 | | #if defined(OS_POSIX) |
50 | | #include <errno.h> |
51 | | #include <pthread.h> |
52 | | #include <stdio.h> |
53 | | #include <stdlib.h> |
54 | | #include <string.h> |
55 | | #include <unistd.h> |
56 | | #define MAX_PATH PATH_MAX |
57 | | typedef FILE* FileHandle; |
58 | | typedef pthread_mutex_t* MutexHandle; |
59 | | #endif |
60 | | |
61 | | #include <algorithm> |
62 | | #include <cstring> |
63 | | #include <ctime> |
64 | | #include <iomanip> |
65 | | #include <ostream> |
66 | | #include <string> |
67 | | |
68 | | #include "butil/file_util.h" |
69 | | #include "butil/debug/alias.h" |
70 | | #include "butil/debug/debugger.h" |
71 | | #include "butil/debug/stack_trace.h" |
72 | | #include "butil/posix/eintr_wrapper.h" |
73 | | #include "butil/strings/string_util.h" |
74 | | #include "butil/strings/stringprintf.h" |
75 | | #include "butil/strings/utf_string_conversions.h" |
76 | | #include "butil/synchronization/condition_variable.h" |
77 | | #include "butil/threading/platform_thread.h" |
78 | | #include "butil/threading/simple_thread.h" |
79 | | #include "butil/object_pool.h" |
80 | | |
81 | | #if defined(OS_POSIX) |
82 | | #include "butil/errno.h" |
83 | | #include "butil/fd_guard.h" |
84 | | #endif |
85 | | #if defined(OS_LINUX) |
86 | | #include <fcntl.h> |
87 | | #endif |
88 | | |
89 | | #if defined(OS_ANDROID) |
90 | | #include <android/log.h> |
91 | | #endif |
92 | | |
93 | | #include <map> |
94 | | #include <vector> |
95 | | #include <deque> |
96 | | #include <limits> |
97 | | #include "butil/atomicops.h" |
98 | | #include "butil/thread_local.h" |
99 | | #include "butil/scoped_lock.h" // BAIDU_SCOPED_LOCK |
100 | | #include "butil/string_splitter.h" |
101 | | #include "butil/time.h" |
102 | | #include "butil/containers/doubly_buffered_data.h" |
103 | | #include "butil/memory/singleton.h" |
104 | | #include "butil/endpoint.h" |
105 | | #include "butil/reloadable_flags.h" |
106 | | #ifdef BAIDU_INTERNAL |
107 | | #include "butil/comlog_sink.h" |
108 | | #endif |
109 | | |
110 | | extern "C" { |
111 | | uint64_t BAIDU_WEAK bthread_self(); |
112 | | typedef struct { |
113 | | uint32_t index; // index in KeyTable |
114 | | uint32_t version; // ABA avoidance |
115 | | } bthread_key_t; |
116 | | int BAIDU_WEAK bthread_key_create(bthread_key_t* key, |
117 | | void (*destructor)(void* data)); |
118 | | int BAIDU_WEAK bthread_setspecific(bthread_key_t key, void* data); |
119 | | void* BAIDU_WEAK bthread_getspecific(bthread_key_t key); |
120 | | } |
121 | | |
122 | | namespace logging { |
123 | | |
124 | | DEFINE_bool(crash_on_fatal_log, false, |
125 | | "Crash process when a FATAL log is printed"); |
126 | | BUTIL_VALIDATE_GFLAG(crash_on_fatal_log, butil::PassValidate); |
127 | | |
128 | | DEFINE_bool(print_stack_on_check, true, |
129 | | "Print the stack trace when a CHECK was failed"); |
130 | | BUTIL_VALIDATE_GFLAG(print_stack_on_check, butil::PassValidate); |
131 | | |
132 | | DEFINE_int32(v, 0, "Show all VLOG(m) messages for m <= this." |
133 | | " Overridable by --vmodule."); |
134 | | DEFINE_string(vmodule, "", "per-module verbose level." |
135 | | " Argument is a comma-separated list of MODULE_NAME=LOG_LEVEL." |
136 | | " MODULE_NAME is a glob pattern, matched against the filename base" |
137 | | " (that is, name ignoring .cpp/.h)." |
138 | | " LOG_LEVEL overrides any value given by --v."); |
139 | | |
140 | | DEFINE_bool(log_pid, false, "Log process id"); |
141 | | |
142 | | DEFINE_bool(log_bid, true, "Log bthread id"); |
143 | | |
144 | | DEFINE_int32(minloglevel, 0, "Any log at or above this level will be " |
145 | | "displayed. Anything below this level will be silently ignored. " |
146 | | "0=INFO 1=NOTICE 2=WARNING 3=ERROR 4=FATAL"); |
147 | | BUTIL_VALIDATE_GFLAG(minloglevel, butil::NonNegativeInteger); |
148 | | |
149 | | DEFINE_bool(log_hostname, false, "Add host after pid in each log so" |
150 | | " that we know where logs came from when using aggregation tools" |
151 | | " like ELK."); |
152 | | |
153 | | DEFINE_bool(log_year, false, "Log year in datetime part in each log"); |
154 | | |
155 | | DEFINE_bool(log_func_name, false, "Log function name in each log"); |
156 | | |
157 | | DEFINE_bool(async_log, false, "Use async log"); |
158 | | |
159 | | DEFINE_bool(async_log_in_background_always, false, "Async log written in background always."); |
160 | | |
161 | | DEFINE_int32(max_async_log_queue_size, 100000, "Max async log size. " |
162 | | "If current log count of async log > max_async_log_size, " |
163 | | "Use sync log to protect process."); |
164 | | |
165 | | DEFINE_int32(sleep_to_flush_async_log_s, 0, |
166 | | "If the value > 0, sleep before atexit to flush async log"); |
167 | | |
168 | | namespace { |
169 | | |
170 | | LoggingDestination logging_destination = LOG_DEFAULT; |
171 | | |
172 | | // For BLOG_ERROR and above, always print to stderr. |
173 | | const int kAlwaysPrintErrorLevel = BLOG_ERROR; |
174 | | |
175 | | // Which log file to use? This is initialized by InitLogging or |
176 | | // will be lazily initialized to the default value when it is |
177 | | // first needed. |
178 | | #if defined(OS_WIN) |
179 | | typedef std::wstring PathString; |
180 | | #else |
181 | | typedef std::string PathString; |
182 | | #endif |
183 | | PathString* log_file_name = NULL; |
184 | | |
185 | | // this file is lazily opened and the handle may be NULL |
186 | | FileHandle log_file = NULL; |
187 | | |
188 | | // Should we pop up fatal debug messages in a dialog? |
189 | | bool show_error_dialogs = false; |
190 | | |
191 | | // An assert handler override specified by the client to be called instead of |
192 | | // the debug message dialog and process termination. |
193 | | LogAssertHandler log_assert_handler = NULL; |
194 | | |
195 | | // Helper functions to wrap platform differences. |
196 | | |
197 | 0 | int32_t CurrentProcessId() { |
198 | | #if defined(OS_WIN) |
199 | | return GetCurrentProcessId(); |
200 | | #elif defined(OS_POSIX) |
201 | | return getpid(); |
202 | 0 | #endif |
203 | 0 | } |
204 | | |
205 | 0 | void DeleteFilePath(const PathString& log_name) { |
206 | | #if defined(OS_WIN) |
207 | | DeleteFile(log_name.c_str()); |
208 | | #elif defined (OS_NACL) |
209 | | // Do nothing; unlink() isn't supported on NaCl. |
210 | | #else |
211 | 0 | unlink(log_name.c_str()); |
212 | 0 | #endif |
213 | 0 | } |
214 | | |
215 | | #if defined(OS_LINUX) |
216 | 0 | static PathString GetProcessName() { |
217 | 0 | butil::fd_guard fd(open("/proc/self/cmdline", O_RDONLY)); |
218 | 0 | if (fd < 0) { |
219 | 0 | return "unknown"; |
220 | 0 | } |
221 | 0 | char buf[512]; |
222 | 0 | const ssize_t len = read(fd, buf, sizeof(buf) - 1); |
223 | 0 | if (len <= 0) { |
224 | 0 | return "unknown"; |
225 | 0 | } |
226 | 0 | buf[len] = '\0'; |
227 | | // Not string(buf, len) because we needs to buf to be truncated at first \0. |
228 | | // Under gdb, the first part of cmdline may include path. |
229 | 0 | return butil::FilePath(std::string(buf)).BaseName().value(); |
230 | 0 | } |
231 | | #endif |
232 | | |
233 | 0 | PathString GetDefaultLogFile() { |
234 | | #if defined(OS_WIN) |
235 | | // On Windows we use the same path as the exe. |
236 | | wchar_t module_name[MAX_PATH]; |
237 | | GetModuleFileName(NULL, module_name, MAX_PATH); |
238 | | |
239 | | PathString log_file = module_name; |
240 | | PathString::size_type last_backslash = |
241 | | log_file.rfind('\\', log_file.size()); |
242 | | if (last_backslash != PathString::npos) |
243 | | log_file.erase(last_backslash + 1); |
244 | | log_file += L"debug.log"; |
245 | | return log_file; |
246 | | #elif defined(OS_LINUX) |
247 | | return GetProcessName() + ".log"; |
248 | | #elif defined(OS_POSIX) |
249 | | // On other platforms we just use the current directory. |
250 | | return PathString("debug.log"); |
251 | | #endif |
252 | 0 | } |
253 | | |
254 | | // This class acts as a wrapper for locking the logging files. |
255 | | // LoggingLock::Init() should be called from the main thread before any logging |
256 | | // is done. Then whenever logging, be sure to have a local LoggingLock |
257 | | // instance on the stack. This will ensure that the lock is unlocked upon |
258 | | // exiting the frame. |
259 | | // LoggingLocks can not be nested. |
260 | | class LoggingLock { |
261 | | public: |
262 | 0 | LoggingLock() { |
263 | 0 | LockLogging(); |
264 | 0 | } |
265 | | |
266 | 0 | ~LoggingLock() { |
267 | 0 | UnlockLogging(); |
268 | 0 | } |
269 | | |
270 | 0 | static void Init(LogLockingState lock_log, const LogChar* new_log_file) { |
271 | 0 | if (initialized) |
272 | 0 | return; |
273 | 0 | lock_log_file = lock_log; |
274 | 0 | if (lock_log_file == LOCK_LOG_FILE) { |
275 | | #if defined(OS_WIN) |
276 | | if (!log_mutex) { |
277 | | std::wstring safe_name; |
278 | | if (new_log_file) |
279 | | safe_name = new_log_file; |
280 | | else |
281 | | safe_name = GetDefaultLogFile(); |
282 | | // \ is not a legal character in mutex names so we replace \ with / |
283 | | std::replace(safe_name.begin(), safe_name.end(), '\\', '/'); |
284 | | std::wstring t(L"Global\\"); |
285 | | t.append(safe_name); |
286 | | log_mutex = ::CreateMutex(NULL, FALSE, t.c_str()); |
287 | | |
288 | | if (log_mutex == NULL) { |
289 | | #if DEBUG |
290 | | // Keep the error code for debugging |
291 | | int error = GetLastError(); // NOLINT |
292 | | butil::debug::BreakDebugger(); |
293 | | #endif |
294 | | // Return nicely without putting initialized to true. |
295 | | return; |
296 | | } |
297 | | } |
298 | | #endif |
299 | 0 | } else { |
300 | 0 | log_lock = new butil::Mutex; |
301 | 0 | } |
302 | 0 | initialized = true; |
303 | 0 | } |
304 | | |
305 | | private: |
306 | 0 | static void LockLogging() { |
307 | 0 | if (lock_log_file == LOCK_LOG_FILE) { |
308 | | #if defined(OS_WIN) |
309 | | ::WaitForSingleObject(log_mutex, INFINITE); |
310 | | // WaitForSingleObject could have returned WAIT_ABANDONED. We don't |
311 | | // abort the process here. UI tests might be crashy sometimes, |
312 | | // and aborting the test binary only makes the problem worse. |
313 | | // We also don't use LOG macros because that might lead to an infinite |
314 | | // loop. For more info see http://crbug.com/18028. |
315 | | #elif defined(OS_POSIX) |
316 | | pthread_mutex_lock(&log_mutex); |
317 | 0 | #endif |
318 | 0 | } else { |
319 | | // use the lock |
320 | 0 | log_lock->lock(); |
321 | 0 | } |
322 | 0 | } |
323 | | |
324 | 0 | static void UnlockLogging() { |
325 | 0 | if (lock_log_file == LOCK_LOG_FILE) { |
326 | | #if defined(OS_WIN) |
327 | | ReleaseMutex(log_mutex); |
328 | | #elif defined(OS_POSIX) |
329 | | pthread_mutex_unlock(&log_mutex); |
330 | 0 | #endif |
331 | 0 | } else { |
332 | 0 | log_lock->unlock(); |
333 | 0 | } |
334 | 0 | } |
335 | | |
336 | | // The lock is used if log file locking is false. It helps us avoid problems |
337 | | // with multiple threads writing to the log file at the same time. |
338 | | static butil::Mutex* log_lock; |
339 | | |
340 | | // When we don't use a lock, we are using a global mutex. We need to do this |
341 | | // because LockFileEx is not thread safe. |
342 | | #if defined(OS_WIN) |
343 | | static MutexHandle log_mutex; |
344 | | #elif defined(OS_POSIX) |
345 | | static pthread_mutex_t log_mutex; |
346 | | #endif |
347 | | |
348 | | static bool initialized; |
349 | | static LogLockingState lock_log_file; |
350 | | }; |
351 | | |
352 | | // static |
353 | | bool LoggingLock::initialized = false; |
354 | | // static |
355 | | butil::Mutex* LoggingLock::log_lock = NULL; |
356 | | // static |
357 | | LogLockingState LoggingLock::lock_log_file = LOCK_LOG_FILE; |
358 | | |
359 | | #if defined(OS_WIN) |
360 | | // static |
361 | | MutexHandle LoggingLock::log_mutex = NULL; |
362 | | #elif defined(OS_POSIX) |
363 | | pthread_mutex_t LoggingLock::log_mutex = PTHREAD_MUTEX_INITIALIZER; |
364 | | #endif |
365 | | |
366 | | // Called by logging functions to ensure that debug_file is initialized |
367 | | // and can be used for writing. Returns false if the file could not be |
368 | | // initialized. debug_file will be NULL in this case. |
369 | 0 | bool InitializeLogFileHandle() { |
370 | 0 | if (log_file) |
371 | 0 | return true; |
372 | | |
373 | 0 | if (!log_file_name) { |
374 | | // Nobody has called InitLogging to specify a debug log file, so here we |
375 | | // initialize the log file name to a default. |
376 | 0 | log_file_name = new PathString(GetDefaultLogFile()); |
377 | 0 | } |
378 | |
|
379 | 0 | if ((logging_destination & LOG_TO_FILE) != 0) { |
380 | | #if defined(OS_WIN) |
381 | | log_file = CreateFile(log_file_name->c_str(), GENERIC_WRITE, |
382 | | FILE_SHARE_READ | FILE_SHARE_WRITE, NULL, |
383 | | OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL); |
384 | | if (log_file == INVALID_HANDLE_VALUE || log_file == NULL) { |
385 | | // try the current directory |
386 | | log_file = CreateFile(L".\\debug.log", GENERIC_WRITE, |
387 | | FILE_SHARE_READ | FILE_SHARE_WRITE, NULL, |
388 | | OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL); |
389 | | if (log_file == INVALID_HANDLE_VALUE || log_file == NULL) { |
390 | | log_file = NULL; |
391 | | return false; |
392 | | } |
393 | | } |
394 | | SetFilePointer(log_file, 0, 0, FILE_END); |
395 | | #elif defined(OS_POSIX) |
396 | | log_file = fopen(log_file_name->c_str(), "a"); |
397 | 0 | if (log_file == NULL) { |
398 | 0 | fprintf(stderr, "Fail to fopen %s", log_file_name->c_str()); |
399 | 0 | return false; |
400 | 0 | } |
401 | 0 | #endif |
402 | 0 | } |
403 | | |
404 | 0 | return true; |
405 | 0 | } |
406 | | |
407 | 0 | void CloseFile(FileHandle log) { |
408 | | #if defined(OS_WIN) |
409 | | CloseHandle(log); |
410 | | #else |
411 | 0 | fclose(log); |
412 | 0 | #endif |
413 | 0 | } |
414 | | |
415 | 0 | void CloseLogFileUnlocked() { |
416 | 0 | if (!log_file) |
417 | 0 | return; |
418 | | |
419 | 0 | CloseFile(log_file); |
420 | 0 | log_file = NULL; |
421 | 0 | } |
422 | | |
423 | 0 | void Log2File(const std::string& log) { |
424 | | // We can have multiple threads and/or processes, so try to prevent them |
425 | | // from clobbering each other's writes. |
426 | | // If the client app did not call InitLogging, and the lock has not |
427 | | // been created do it now. We do this on demand, but if two threads try |
428 | | // to do this at the same time, there will be a race condition to create |
429 | | // the lock. This is why InitLogging should be called from the main |
430 | | // thread at the beginning of execution. |
431 | 0 | LoggingLock::Init(LOCK_LOG_FILE, NULL); |
432 | 0 | LoggingLock logging_lock; |
433 | 0 | if (InitializeLogFileHandle()) { |
434 | | #if defined(OS_WIN) |
435 | | SetFilePointer(log_file, 0, 0, SEEK_END); |
436 | | DWORD num_written; |
437 | | WriteFile(log_file, static_cast<const void*>(log.data()), |
438 | | static_cast<DWORD>(log.size()), &num_written, NULL); |
439 | | #else |
440 | 0 | fwrite(log.data(), log.size(), 1, log_file); |
441 | 0 | fflush(log_file); |
442 | 0 | #endif |
443 | 0 | } |
444 | 0 | } |
445 | | |
446 | | } // namespace |
447 | | |
448 | | #if defined(OS_LINUX) || defined(OS_MACOSX) |
449 | | typedef timeval TimeVal; |
450 | | #else |
451 | | struct TimeVal { |
452 | | time_t tv_sec; |
453 | | }; |
454 | | #endif |
455 | | |
456 | 23.5k | TimeVal GetTimestamp() { |
457 | 23.5k | #if defined(OS_LINUX) || defined(OS_MACOSX) |
458 | 23.5k | timeval tv; |
459 | 23.5k | gettimeofday(&tv, NULL); |
460 | 23.5k | return tv; |
461 | | #else |
462 | | return { time(NULL) }; |
463 | | #endif |
464 | 23.5k | } |
465 | | |
466 | | struct BAIDU_CACHELINE_ALIGNMENT LogInfo { |
467 | | std::string file; |
468 | | std::string func; |
469 | | std::string content; |
470 | | TimeVal timestamp{}; |
471 | | int severity{0}; |
472 | | int line{0}; |
473 | | // If `raw' is false, content has been a complete log. |
474 | | // If raw is true, a complete log consists of all properties of LogInfo. |
475 | | bool raw{false}; |
476 | | }; |
477 | | |
478 | | struct BAIDU_CACHELINE_ALIGNMENT LogRequest { |
479 | | static LogRequest* const UNCONNECTED; |
480 | | |
481 | | LogRequest* next{NULL}; |
482 | | LogInfo log_info; |
483 | | }; |
484 | | |
485 | | LogRequest* const LogRequest::UNCONNECTED = (LogRequest*)(intptr_t)-1; |
486 | | |
487 | | class AsyncLogger : public butil::SimpleThread { |
488 | | public: |
489 | | static AsyncLogger* GetInstance(); |
490 | | |
491 | | void Log(const LogInfo& log_info); |
492 | | void Log(LogInfo&& log_info); |
493 | | void StopAndJoin(); |
494 | | |
495 | | private: |
496 | | friend struct DefaultSingletonTraits<AsyncLogger>; |
497 | | |
498 | | static LogRequest _stop_req; |
499 | | |
500 | | AsyncLogger(); |
501 | | ~AsyncLogger() override; |
502 | | |
503 | 0 | static void AtExit() { |
504 | 0 | GetInstance()->StopAndJoin(); |
505 | 0 | if (FLAGS_sleep_to_flush_async_log_s > 0) { |
506 | 0 | ::sleep(FLAGS_sleep_to_flush_async_log_s); |
507 | 0 | } |
508 | 0 | } |
509 | | |
510 | | void LogImpl(LogRequest* log_req); |
511 | | |
512 | | void Run() override; |
513 | | |
514 | | void LogTask(LogRequest* req); |
515 | | |
516 | | bool IsLogComplete(LogRequest* old_head); |
517 | | |
518 | | void DoLog(LogRequest* req); |
519 | | void DoLog(const LogInfo& log_info); |
520 | | |
521 | | butil::atomic<LogRequest*> _log_head; |
522 | | butil::Mutex _mutex; |
523 | | butil::ConditionVariable _cond; |
524 | | LogRequest* _current_log_request; |
525 | | butil::atomic<int32_t> _log_request_count; |
526 | | butil::atomic<bool> _stop; |
527 | | }; |
528 | | |
529 | 0 | AsyncLogger* AsyncLogger::GetInstance() { |
530 | 0 | return Singleton<AsyncLogger, |
531 | 0 | LeakySingletonTraits<AsyncLogger>>::get(); |
532 | 0 | } |
533 | | |
534 | | AsyncLogger::AsyncLogger() |
535 | 0 | : butil::SimpleThread("async_log_thread") |
536 | 0 | , _log_head(NULL) |
537 | 0 | , _cond(&_mutex) |
538 | | , _current_log_request(NULL) |
539 | 0 | , _stop(false) { |
540 | 0 | Start(); |
541 | | // We need to stop async logger and |
542 | | // flush all async log before exit. |
543 | 0 | atexit(AtExit); |
544 | 0 | } |
545 | | |
546 | 0 | AsyncLogger::~AsyncLogger() { |
547 | 0 | StopAndJoin(); |
548 | 0 | } |
549 | | |
550 | | std::string LogInfoToLogStr(int severity, butil::StringPiece file, |
551 | | int line, butil::StringPiece func, |
552 | 23.5k | butil::StringPiece content) { |
553 | | // There's a copy here to concatenate prefix and content. Since |
554 | | // DefaultLogSink is hardly used right now, the copy is irrelevant. |
555 | | // A LogSink focused on performance should also be able to handle |
556 | | // non-continuous inputs which is a must to maximize performance. |
557 | 23.5k | std::ostringstream os; |
558 | 23.5k | PrintLog(os, severity, file.data(), line, func.data(), content); |
559 | 23.5k | os << '\n'; |
560 | 23.5k | return os.str(); |
561 | 23.5k | } |
562 | | |
563 | 0 | std::string LogInfo2LogStr(const LogInfo& log_info) { |
564 | 0 | return LogInfoToLogStr(log_info.severity, log_info.file, log_info.line, |
565 | 0 | log_info.func, log_info.content); |
566 | 0 | } |
567 | | |
568 | 0 | void AsyncLogger::Log(const LogInfo& log_info) { |
569 | 0 | if (log_info.content.empty()) { |
570 | 0 | return; |
571 | 0 | } |
572 | | |
573 | 0 | bool is_full = FLAGS_max_async_log_queue_size > 0 && |
574 | 0 | _log_request_count.fetch_add(1, butil::memory_order_relaxed) > |
575 | 0 | FLAGS_max_async_log_queue_size; |
576 | 0 | if (is_full || _stop.load(butil::memory_order_relaxed)) { |
577 | | // Async logger is full or stopped, fallback to sync log. |
578 | 0 | DoLog(log_info); |
579 | 0 | return; |
580 | 0 | } |
581 | | |
582 | 0 | auto log_req = butil::get_object<LogRequest>(); |
583 | 0 | if (!log_req) { |
584 | | // Async log failed, fallback to sync log. |
585 | 0 | DoLog(log_info); |
586 | 0 | return; |
587 | 0 | } |
588 | 0 | log_req->log_info = log_info; |
589 | 0 | LogImpl(log_req); |
590 | 0 | } |
591 | | |
592 | 0 | void AsyncLogger::Log(LogInfo&& log_info) { |
593 | 0 | if (log_info.content.empty()) { |
594 | 0 | return; |
595 | 0 | } |
596 | | |
597 | 0 | bool is_full = FLAGS_max_async_log_queue_size > 0 && |
598 | 0 | _log_request_count.fetch_add(1, butil::memory_order_relaxed) > |
599 | 0 | FLAGS_max_async_log_queue_size; |
600 | 0 | if (is_full || _stop.load(butil::memory_order_relaxed)) { |
601 | | // Async logger is full or stopped, fallback to sync log. |
602 | 0 | DoLog(log_info); |
603 | 0 | return; |
604 | 0 | } |
605 | | |
606 | 0 | auto log_req = butil::get_object<LogRequest>(); |
607 | 0 | if (!log_req) { |
608 | | // Async log failed, fallback to sync log. |
609 | 0 | DoLog(log_info); |
610 | 0 | return; |
611 | 0 | } |
612 | 0 | log_req->log_info = std::move(log_info); |
613 | 0 | LogImpl(log_req); |
614 | 0 | } |
615 | | |
616 | 0 | void AsyncLogger::LogImpl(LogRequest* log_req) { |
617 | 0 | log_req->next = LogRequest::UNCONNECTED; |
618 | | // Release fence makes sure the thread getting request sees *req |
619 | 0 | LogRequest* const prev_head = |
620 | 0 | _log_head.exchange(log_req, butil::memory_order_release); |
621 | 0 | if (prev_head != NULL) { |
622 | | // Someone is logging. The async_log_thread thread may spin |
623 | | // until req->next to be non-UNCONNECTED. This process is not |
624 | | // lock-free, but the duration is so short(1~2 instructions, |
625 | | // depending on compiler) that the spin rarely occurs in practice |
626 | | // (I've not seen any spin in highly contended tests). |
627 | 0 | log_req->next = prev_head; |
628 | 0 | return; |
629 | 0 | } |
630 | | // We've got the right to write. |
631 | 0 | log_req->next = NULL; |
632 | |
|
633 | 0 | if (!FLAGS_async_log_in_background_always) { |
634 | | // Use sync log for the LogRequest |
635 | | // which has got the right to write. |
636 | 0 | DoLog(log_req); |
637 | | // Return when there's no more LogRequests. |
638 | 0 | if (IsLogComplete(log_req)) { |
639 | 0 | butil::return_object(log_req); |
640 | 0 | return; |
641 | 0 | } |
642 | 0 | } |
643 | | |
644 | 0 | BAIDU_SCOPED_LOCK(_mutex); |
645 | 0 | if (_stop.load(butil::memory_order_relaxed)) { |
646 | | // Async logger is stopped, fallback to sync log. |
647 | 0 | LogTask(log_req); |
648 | 0 | } else { |
649 | | // Wake up async logger. |
650 | 0 | _current_log_request = log_req; |
651 | 0 | _cond.Signal(); |
652 | 0 | } |
653 | 0 | } |
654 | | |
655 | 0 | void AsyncLogger::StopAndJoin() { |
656 | 0 | if (!_stop.exchange(true, butil::memory_order_relaxed)) { |
657 | 0 | BAIDU_SCOPED_LOCK(_mutex); |
658 | 0 | _cond.Signal(); |
659 | 0 | } |
660 | 0 | if (!HasBeenJoined()) { |
661 | 0 | Join(); |
662 | 0 | } |
663 | 0 | } |
664 | | |
665 | 0 | void AsyncLogger::Run() { |
666 | 0 | while (true) { |
667 | 0 | BAIDU_SCOPED_LOCK(_mutex); |
668 | 0 | while (!_stop.load(butil::memory_order_relaxed) && |
669 | 0 | !_current_log_request) { |
670 | 0 | _cond.Wait(); |
671 | 0 | } |
672 | 0 | if (_stop.load(butil::memory_order_relaxed) && |
673 | 0 | !_current_log_request) { |
674 | 0 | break; |
675 | 0 | } |
676 | | |
677 | 0 | LogTask(_current_log_request); |
678 | 0 | _current_log_request = NULL; |
679 | 0 | } |
680 | 0 | } |
681 | | |
682 | 0 | void AsyncLogger::LogTask(LogRequest* req) { |
683 | 0 | do { |
684 | | // req was logged, skip it. |
685 | 0 | if (req->next != NULL && req->log_info.content.empty()) { |
686 | 0 | LogRequest* const saved_req = req; |
687 | 0 | req = req->next; |
688 | 0 | butil::return_object(saved_req); |
689 | 0 | } |
690 | | |
691 | | // Log all requests to file. |
692 | 0 | while (req->next != NULL) { |
693 | 0 | LogRequest* const saved_req = req; |
694 | 0 | req = req->next; |
695 | 0 | if (!saved_req->log_info.content.empty()) { |
696 | 0 | DoLog(saved_req); |
697 | 0 | } |
698 | | // Release LogRequests until last request. |
699 | 0 | butil::return_object(saved_req); |
700 | 0 | } |
701 | 0 | if (!req->log_info.content.empty()) { |
702 | 0 | DoLog(req); |
703 | 0 | } |
704 | | |
705 | | // Return when there's no more LogRequests. |
706 | 0 | if (IsLogComplete(req)) { |
707 | 0 | butil::return_object(req); |
708 | 0 | return; |
709 | 0 | } |
710 | 0 | } while (true); |
711 | 0 | } |
712 | | |
713 | 0 | bool AsyncLogger::IsLogComplete(LogRequest* old_head) { |
714 | 0 | if (old_head->next) { |
715 | 0 | fprintf(stderr, "old_head->next should be NULL\n"); |
716 | 0 | } |
717 | 0 | LogRequest* new_head = old_head; |
718 | 0 | LogRequest* desired = NULL; |
719 | 0 | if (_log_head.compare_exchange_strong( |
720 | 0 | new_head, desired, butil::memory_order_acquire)) { |
721 | | // No one added new requests. |
722 | 0 | return true; |
723 | 0 | } |
724 | 0 | if (new_head == old_head) { |
725 | 0 | fprintf(stderr, "new_head should not be equal to old_head\n"); |
726 | 0 | } |
727 | | // Above acquire fence pairs release fence of exchange in Log() to make |
728 | | // sure that we see all fields of requests set. |
729 | | |
730 | | // Someone added new requests. |
731 | | // Reverse the list until old_head. |
732 | 0 | LogRequest* tail = NULL; |
733 | 0 | LogRequest* p = new_head; |
734 | 0 | do { |
735 | 0 | while (p->next == LogRequest::UNCONNECTED) { |
736 | 0 | sched_yield(); |
737 | 0 | } |
738 | 0 | LogRequest* const saved_next = p->next; |
739 | 0 | p->next = tail; |
740 | 0 | tail = p; |
741 | 0 | p = saved_next; |
742 | 0 | if (!p) { |
743 | 0 | fprintf(stderr, "p should not be NULL\n"); |
744 | 0 | } |
745 | 0 | } while (p != old_head); |
746 | | |
747 | | // Link old list with new list. |
748 | 0 | old_head->next = tail; |
749 | 0 | return false; |
750 | 0 | } |
751 | | |
752 | 0 | void AsyncLogger::DoLog(LogRequest* req) { |
753 | 0 | DoLog(req->log_info); |
754 | 0 | req->log_info.content.clear(); |
755 | 0 | } |
756 | | |
757 | 0 | void AsyncLogger::DoLog(const LogInfo& log_info) { |
758 | 0 | if (log_info.raw) { |
759 | 0 | Log2File(LogInfo2LogStr(log_info)); |
760 | 0 | } else { |
761 | 0 | Log2File(log_info.content); |
762 | 0 | } |
763 | 0 | _log_request_count.fetch_sub(1, butil::memory_order_relaxed); |
764 | 0 | } |
765 | | |
766 | | LoggingSettings::LoggingSettings() |
767 | 0 | : logging_dest(LOG_DEFAULT), |
768 | | log_file(NULL), |
769 | 0 | lock_log(LOCK_LOG_FILE), |
770 | 0 | delete_old(APPEND_TO_OLD_LOG_FILE) {} |
771 | | |
772 | 0 | bool BaseInitLoggingImpl(const LoggingSettings& settings) { |
773 | | #if defined(OS_NACL) |
774 | | // Can log only to the system debug log. |
775 | | CHECK_EQ(settings.logging_dest & ~LOG_TO_SYSTEM_DEBUG_LOG, 0); |
776 | | #endif |
777 | |
|
778 | 0 | logging_destination = settings.logging_dest; |
779 | | |
780 | | // ignore file options unless logging to file is set. |
781 | 0 | if ((logging_destination & LOG_TO_FILE) == 0) |
782 | 0 | return true; |
783 | | |
784 | 0 | LoggingLock::Init(settings.lock_log, settings.log_file); |
785 | 0 | LoggingLock logging_lock; |
786 | | |
787 | | // Calling InitLogging twice or after some log call has already opened the |
788 | | // default log file will re-initialize to the new options. |
789 | 0 | CloseLogFileUnlocked(); |
790 | |
|
791 | 0 | if (!log_file_name) |
792 | 0 | log_file_name = new PathString(); |
793 | 0 | if (settings.log_file) { |
794 | 0 | *log_file_name = settings.log_file; |
795 | 0 | } else { |
796 | 0 | *log_file_name = GetDefaultLogFile(); |
797 | 0 | } |
798 | 0 | if (settings.delete_old == DELETE_OLD_LOG_FILE) |
799 | 0 | DeleteFilePath(*log_file_name); |
800 | |
|
801 | 0 | return InitializeLogFileHandle(); |
802 | 0 | } |
803 | | |
804 | 0 | void SetMinLogLevel(int level) { |
805 | 0 | FLAGS_minloglevel = std::min(BLOG_FATAL, level); |
806 | 0 | } |
807 | | |
808 | 23.3k | int GetMinLogLevel() { |
809 | 23.3k | return FLAGS_minloglevel; |
810 | 23.3k | } |
811 | | |
812 | 0 | void SetShowErrorDialogs(bool enable_dialogs) { |
813 | 0 | show_error_dialogs = enable_dialogs; |
814 | 0 | } |
815 | | |
816 | 0 | void SetLogAssertHandler(LogAssertHandler handler) { |
817 | 0 | log_assert_handler = handler; |
818 | 0 | } |
819 | | |
820 | | const char* const log_severity_names[LOG_NUM_SEVERITIES] = { |
821 | | "INFO", "NOTICE", "WARNING", "ERROR", "FATAL" }; |
822 | | |
823 | 23.5k | static void PrintLogSeverity(std::ostream& os, int severity) { |
824 | 23.5k | if (severity < 0) { |
825 | | // Add extra space to separate from following datetime. |
826 | 0 | os << 'V' << -severity << ' '; |
827 | 23.5k | } else if (severity < LOG_NUM_SEVERITIES) { |
828 | 23.5k | os << log_severity_names[severity][0]; |
829 | 23.5k | } else { |
830 | 0 | os << 'U'; |
831 | 0 | } |
832 | 23.5k | } |
833 | | |
834 | | void PrintLogPrefix(std::ostream& os, int severity, |
835 | | butil::StringPiece file, int line, |
836 | 23.5k | butil::StringPiece func, TimeVal tv) { |
837 | 23.5k | PrintLogSeverity(os, severity); |
838 | 23.5k | time_t t = tv.tv_sec; |
839 | 23.5k | struct tm local_tm = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, NULL}; |
840 | | #if _MSC_VER >= 1400 |
841 | | localtime_s(&local_tm, &t); |
842 | | #else |
843 | 23.5k | localtime_r(&t, &local_tm); |
844 | 23.5k | #endif |
845 | 23.5k | const char prev_fill = os.fill('0'); |
846 | 23.5k | if (FLAGS_log_year) { |
847 | 0 | os << std::setw(4) << local_tm.tm_year + 1900; |
848 | 0 | } |
849 | 23.5k | os << std::setw(2) << local_tm.tm_mon + 1 |
850 | 23.5k | << std::setw(2) << local_tm.tm_mday << ' ' |
851 | 23.5k | << std::setw(2) << local_tm.tm_hour << ':' |
852 | 23.5k | << std::setw(2) << local_tm.tm_min << ':' |
853 | 23.5k | << std::setw(2) << local_tm.tm_sec; |
854 | 23.5k | #if defined(OS_LINUX) || defined(OS_MACOSX) |
855 | 23.5k | os << '.' << std::setw(6) << tv.tv_usec; |
856 | 23.5k | #endif |
857 | 23.5k | if (FLAGS_log_pid) { |
858 | 0 | os << ' ' << std::setfill(' ') << std::setw(5) << CurrentProcessId(); |
859 | 0 | } |
860 | 23.5k | os << ' ' << std::setfill(' ') << std::setw(5) |
861 | 23.5k | << butil::PlatformThread::CurrentId() << std::setfill('0'); |
862 | 23.5k | if (FLAGS_log_bid && bthread_self) { |
863 | 23.5k | os << ' ' << std::setfill(' ') << std::setw(5) << bthread_self(); |
864 | 23.5k | } |
865 | 23.5k | if (FLAGS_log_hostname) { |
866 | 0 | butil::StringPiece hostname(butil::my_hostname()); |
867 | 0 | if (hostname.ends_with(".baidu.com")) { // make it shorter |
868 | 0 | hostname.remove_suffix(10); |
869 | 0 | } |
870 | 0 | os << ' ' << hostname; |
871 | 0 | } |
872 | 23.5k | os << ' ' << file << ':' << line; |
873 | 23.5k | if (!func.empty()) { |
874 | 0 | os << " " << func; |
875 | 0 | } |
876 | 23.5k | os << "] "; |
877 | | |
878 | 23.5k | os.fill(prev_fill); |
879 | 23.5k | } |
880 | | |
881 | | void PrintLogPrefix(std::ostream& os, int severity, |
882 | 0 | const char* file, int line) { |
883 | 0 | PrintLogPrefix(os, severity, file, line, "", GetTimestamp()); |
884 | 0 | } |
885 | | |
886 | | static void PrintLogPrefixAsJSON(std::ostream& os, int severity, |
887 | | butil::StringPiece file, |
888 | | butil::StringPiece func, |
889 | 0 | int line, TimeVal tv) { |
890 | | // severity |
891 | 0 | os << "\"L\":\""; |
892 | 0 | if (severity < 0) { |
893 | 0 | os << 'V' << -severity; |
894 | 0 | } else if (severity < LOG_NUM_SEVERITIES) { |
895 | 0 | os << log_severity_names[severity][0]; |
896 | 0 | } else { |
897 | 0 | os << 'U'; |
898 | 0 | } |
899 | | // time |
900 | 0 | os << "\",\"T\":\""; |
901 | 0 | time_t t = tv.tv_sec; |
902 | 0 | struct tm local_tm = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, NULL}; |
903 | | #if _MSC_VER >= 1400 |
904 | | localtime_s(&local_tm, &t); |
905 | | #else |
906 | 0 | localtime_r(&t, &local_tm); |
907 | 0 | #endif |
908 | 0 | const char prev_fill = os.fill('0'); |
909 | 0 | if (FLAGS_log_year) { |
910 | 0 | os << std::setw(4) << local_tm.tm_year + 1900; |
911 | 0 | } |
912 | 0 | os << std::setw(2) << local_tm.tm_mon + 1 |
913 | 0 | << std::setw(2) << local_tm.tm_mday << ' ' |
914 | 0 | << std::setw(2) << local_tm.tm_hour << ':' |
915 | 0 | << std::setw(2) << local_tm.tm_min << ':' |
916 | 0 | << std::setw(2) << local_tm.tm_sec; |
917 | 0 | #if defined(OS_LINUX) || defined(OS_MACOSX) |
918 | 0 | os << '.' << std::setw(6) << tv.tv_usec; |
919 | 0 | #endif |
920 | 0 | os << "\","; |
921 | 0 | os.fill(prev_fill); |
922 | |
|
923 | 0 | if (FLAGS_log_pid) { |
924 | 0 | os << "\"pid\":\"" << CurrentProcessId() << "\","; |
925 | 0 | } |
926 | 0 | os << "\"tid\":\"" << butil::PlatformThread::CurrentId() << "\","; |
927 | 0 | if (FLAGS_log_hostname) { |
928 | 0 | butil::StringPiece hostname(butil::my_hostname()); |
929 | 0 | if (hostname.ends_with(".baidu.com")) { // make it shorter |
930 | 0 | hostname.remove_suffix(10); |
931 | 0 | } |
932 | 0 | os << "\"host\":\"" << hostname << "\","; |
933 | 0 | } |
934 | 0 | os << "\"C\":\"" << file << ':' << line; |
935 | 0 | if (!func.empty()) { |
936 | 0 | os << " " << func; |
937 | 0 | } |
938 | 0 | os << "\""; |
939 | 0 | } |
940 | | |
941 | 0 | void EscapeJson(std::ostream& os, const butil::StringPiece& s) { |
942 | 0 | for (auto it = s.begin(); it != s.end(); it++) { |
943 | 0 | auto c = *it; |
944 | 0 | switch (c) { |
945 | 0 | case '"': os << "\\\""; break; |
946 | 0 | case '\\': os << "\\\\"; break; |
947 | 0 | case '\b': os << "\\b"; break; |
948 | 0 | case '\f': os << "\\f"; break; |
949 | 0 | case '\n': os << "\\n"; break; |
950 | 0 | case '\r': os << "\\r"; break; |
951 | 0 | case '\t': os << "\\t"; break; |
952 | 0 | default: os << c; |
953 | 0 | } |
954 | 0 | } |
955 | 0 | } |
956 | | |
957 | 23.5k | inline void OutputLog(std::ostream& os, const butil::StringPiece& s) { |
958 | 23.5k | if (FLAGS_escape_log) { |
959 | 0 | EscapeJson(os, s); |
960 | 23.5k | } else { |
961 | 23.5k | os.write(s.data(), s.length()); |
962 | 23.5k | } |
963 | 23.5k | } |
964 | | |
965 | | void PrintLog(std::ostream& os, int severity, const char* file, int line, |
966 | 23.5k | const char* func, const butil::StringPiece& content) { |
967 | 23.5k | if (!FLAGS_log_as_json) { |
968 | 23.5k | PrintLogPrefix(os, severity, file, line, func, GetTimestamp()); |
969 | 23.5k | OutputLog(os, content); |
970 | 23.5k | } else { |
971 | 0 | os << '{'; |
972 | 0 | PrintLogPrefixAsJSON(os, severity, file, func, line, GetTimestamp()); |
973 | 0 | bool pair_quote = false; |
974 | 0 | if (content.empty() || content[0] != '"') { |
975 | | // not a json, add a 'M' field |
976 | 0 | os << ",\"M\":\""; |
977 | 0 | pair_quote = true; |
978 | 0 | } else { |
979 | 0 | os << ','; |
980 | 0 | } |
981 | 0 | OutputLog(os, content); |
982 | 0 | if (pair_quote) { |
983 | 0 | os << '"'; |
984 | 0 | } else if (!content.empty() && content[content.size() -1 ] != '"') { |
985 | | // Controller may write `"M":"...` which misses the last quote |
986 | 0 | os << '"'; |
987 | 0 | } |
988 | 0 | os << '}'; |
989 | 0 | } |
990 | 23.5k | } |
991 | | |
992 | | void PrintLog(std::ostream& os, |
993 | | int severity, const char* file, int line, |
994 | 0 | const butil::StringPiece& content) { |
995 | 0 | PrintLog(os, severity, file, line, "", content); |
996 | 0 | } |
997 | | |
998 | | // A log message handler that gets notified of every log message we process. |
999 | | class DoublyBufferedLogSink : public butil::DoublyBufferedData<LogSink*> { |
1000 | | public: |
1001 | 5 | DoublyBufferedLogSink() {} |
1002 | | static DoublyBufferedLogSink* GetInstance(); |
1003 | | private: |
1004 | | friend struct DefaultSingletonTraits<DoublyBufferedLogSink>; |
1005 | | DISALLOW_COPY_AND_ASSIGN(DoublyBufferedLogSink); |
1006 | | }; |
1007 | | |
1008 | 23.5k | DoublyBufferedLogSink* DoublyBufferedLogSink::GetInstance() { |
1009 | 23.5k | return Singleton<DoublyBufferedLogSink, |
1010 | 23.5k | LeakySingletonTraits<DoublyBufferedLogSink> >::get(); |
1011 | 23.5k | } |
1012 | | |
1013 | | struct SetLogSinkFn { |
1014 | | LogSink* new_sink; |
1015 | | LogSink* old_sink; |
1016 | | |
1017 | 0 | bool operator()(LogSink*& ptr) { |
1018 | 0 | old_sink = ptr; |
1019 | 0 | ptr = new_sink; |
1020 | 0 | return true; |
1021 | 0 | } |
1022 | | }; |
1023 | | |
1024 | 0 | LogSink* SetLogSink(LogSink* sink) { |
1025 | 0 | SetLogSinkFn fn = { sink, NULL }; |
1026 | 0 | CHECK(DoublyBufferedLogSink::GetInstance()->Modify(fn)); |
1027 | 0 | return fn.old_sink; |
1028 | 0 | } |
1029 | | |
1030 | | // MSVC doesn't like complex extern templates and DLLs. |
1031 | | #if !defined(COMPILER_MSVC) |
1032 | | // Explicit instantiations for commonly used comparisons. |
1033 | | template std::string* MakeCheckOpString<int, int>( |
1034 | | const int&, const int&, const char* names); |
1035 | | template std::string* MakeCheckOpString<unsigned long, unsigned long>( |
1036 | | const unsigned long&, const unsigned long&, const char* names); |
1037 | | template std::string* MakeCheckOpString<unsigned long, unsigned int>( |
1038 | | const unsigned long&, const unsigned int&, const char* names); |
1039 | | template std::string* MakeCheckOpString<unsigned int, unsigned long>( |
1040 | | const unsigned int&, const unsigned long&, const char* names); |
1041 | | template std::string* MakeCheckOpString<std::string, std::string>( |
1042 | | const std::string&, const std::string&, const char* name); |
1043 | | #endif |
1044 | | |
1045 | | #if !defined(NDEBUG) |
1046 | | // Displays a message box to the user with the error message in it. |
1047 | | // Used for fatal messages, where we close the app simultaneously. |
1048 | | // This is for developers only; we don't use this in circumstances |
1049 | | // (like release builds) where users could see it, since users don't |
1050 | | // understand these messages anyway. |
1051 | 0 | void DisplayDebugMessageInDialog(const std::string& str) { |
1052 | 0 | if (str.empty()) |
1053 | 0 | return; |
1054 | | |
1055 | 0 | if (!show_error_dialogs) |
1056 | 0 | return; |
1057 | |
|
1058 | | #if defined(OS_WIN) |
1059 | | // For Windows programs, it's possible that the message loop is |
1060 | | // messed up on a fatal error, and creating a MessageBox will cause |
1061 | | // that message loop to be run. Instead, we try to spawn another |
1062 | | // process that displays its command line. We look for "Debug |
1063 | | // Message.exe" in the same directory as the application. If it |
1064 | | // exists, we use it, otherwise, we use a regular message box. |
1065 | | wchar_t prog_name[MAX_PATH]; |
1066 | | GetModuleFileNameW(NULL, prog_name, MAX_PATH); |
1067 | | wchar_t* backslash = wcsrchr(prog_name, '\\'); |
1068 | | if (backslash) |
1069 | | backslash[1] = 0; |
1070 | | wcscat_s(prog_name, MAX_PATH, L"debug_message.exe"); |
1071 | | |
1072 | | std::wstring cmdline = butil::UTF8ToWide(str); |
1073 | | if (cmdline.empty()) |
1074 | | return; |
1075 | | |
1076 | | STARTUPINFO startup_info; |
1077 | | memset(&startup_info, 0, sizeof(startup_info)); |
1078 | | startup_info.cb = sizeof(startup_info); |
1079 | | |
1080 | | PROCESS_INFORMATION process_info; |
1081 | | if (CreateProcessW(prog_name, &cmdline[0], NULL, NULL, false, 0, NULL, |
1082 | | NULL, &startup_info, &process_info)) { |
1083 | | WaitForSingleObject(process_info.hProcess, INFINITE); |
1084 | | CloseHandle(process_info.hThread); |
1085 | | CloseHandle(process_info.hProcess); |
1086 | | } else { |
1087 | | // debug process broken, let's just do a message box |
1088 | | MessageBoxW(NULL, &cmdline[0], L"Fatal error", |
1089 | | MB_OK | MB_ICONHAND | MB_TOPMOST); |
1090 | | } |
1091 | | #else |
1092 | | // We intentionally don't implement a dialog on other platforms. |
1093 | | // You can just look at stderr. |
1094 | 0 | #endif |
1095 | 0 | } |
1096 | | #endif // !defined(NDEBUG) |
1097 | | |
1098 | | |
1099 | | bool StringSink::OnLogMessage(int severity, const char* file, int line, |
1100 | 0 | const butil::StringPiece& content) { |
1101 | 0 | return OnLogMessage(severity, file, line, "", content); |
1102 | 0 | } |
1103 | | |
1104 | | bool StringSink::OnLogMessage(int severity, const char* file, |
1105 | | int line, const char* func, |
1106 | 0 | const butil::StringPiece& content) { |
1107 | 0 | std::ostringstream os; |
1108 | 0 | PrintLog(os, severity, file, line, func, content); |
1109 | 0 | const std::string msg = os.str(); |
1110 | 0 | { |
1111 | 0 | butil::AutoLock lock_guard(_lock); |
1112 | 0 | append(msg); |
1113 | 0 | } |
1114 | 0 | return true; |
1115 | 0 | } |
1116 | | |
1117 | 0 | CharArrayStreamBuf::~CharArrayStreamBuf() { |
1118 | 0 | free(_data); |
1119 | 0 | } |
1120 | | |
1121 | 28 | int CharArrayStreamBuf::overflow(int ch) { |
1122 | 28 | if (ch == std::streambuf::traits_type::eof()) { |
1123 | 0 | return ch; |
1124 | 0 | } |
1125 | 28 | size_t new_size = std::max(_size * 3 / 2, (size_t)64); |
1126 | 28 | char* new_data = (char*)malloc(new_size); |
1127 | 28 | if (BAIDU_UNLIKELY(new_data == NULL)) { |
1128 | 0 | setp(NULL, NULL); |
1129 | 0 | return std::streambuf::traits_type::eof(); |
1130 | 0 | } |
1131 | 28 | memcpy(new_data, _data, _size); |
1132 | 28 | free(_data); |
1133 | 28 | _data = new_data; |
1134 | 28 | const size_t old_size = _size; |
1135 | 28 | _size = new_size; |
1136 | 28 | setp(_data, _data + new_size); |
1137 | 28 | pbump(old_size); |
1138 | | // if size == 1, this function will call overflow again. |
1139 | 28 | return sputc(ch); |
1140 | 28 | } |
1141 | | |
1142 | 137 | int CharArrayStreamBuf::sync() { |
1143 | | // data are already there. |
1144 | 137 | return 0; |
1145 | 137 | } |
1146 | | |
1147 | 23.5k | void CharArrayStreamBuf::reset() { |
1148 | 23.5k | setp(_data, _data + _size); |
1149 | 23.5k | } |
1150 | | |
1151 | | LogStream& LogStream::SetPosition(const LogChar* file, int line, |
1152 | 0 | LogSeverity severity) { |
1153 | 0 | _file = file; |
1154 | 0 | _line = line; |
1155 | 0 | _severity = severity; |
1156 | 0 | return *this; |
1157 | 0 | } |
1158 | | |
1159 | | LogStream& LogStream::SetPosition(const LogChar* file, int line, |
1160 | | const LogChar* func, |
1161 | 23.5k | LogSeverity severity) { |
1162 | 23.5k | _file = file; |
1163 | 23.5k | _line = line; |
1164 | 23.5k | _func = func; |
1165 | 23.5k | _severity = severity; |
1166 | 23.5k | return *this; |
1167 | 23.5k | } |
1168 | | |
1169 | | #if defined(__GNUC__) |
1170 | | static bthread_key_t stream_bkey; |
1171 | | static pthread_key_t stream_pkey; |
1172 | | static pthread_once_t create_stream_key_once = PTHREAD_ONCE_INIT; |
1173 | 23.5k | inline bool is_bthread_linked() { return bthread_key_create != NULL; } |
1174 | 0 | static void destroy_tls_streams(void* data) { |
1175 | 0 | if (data == NULL) { |
1176 | 0 | return; |
1177 | 0 | } |
1178 | 0 | LogStream** a = (LogStream**)data; |
1179 | 0 | for (int i = 0; i <= LOG_NUM_SEVERITIES; ++i) { |
1180 | 0 | delete a[i]; |
1181 | 0 | } |
1182 | 0 | delete[] a; |
1183 | 0 | } |
1184 | 5 | static void create_stream_key_or_die() { |
1185 | 5 | if (is_bthread_linked()) { |
1186 | 5 | int rc = bthread_key_create(&stream_bkey, destroy_tls_streams); |
1187 | 5 | if (rc) { |
1188 | 0 | fprintf(stderr, "Fail to bthread_key_create"); |
1189 | 0 | exit(1); |
1190 | 0 | } |
1191 | 5 | } else { |
1192 | 0 | int rc = pthread_key_create(&stream_pkey, destroy_tls_streams); |
1193 | 0 | if (rc) { |
1194 | 0 | fprintf(stderr, "Fail to pthread_key_create"); |
1195 | 0 | exit(1); |
1196 | 0 | } |
1197 | 0 | } |
1198 | 5 | } |
1199 | 23.5k | static LogStream** get_tls_stream_array() { |
1200 | 23.5k | pthread_once(&create_stream_key_once, create_stream_key_or_die); |
1201 | 23.5k | if (is_bthread_linked()) { |
1202 | 23.5k | return (LogStream**)bthread_getspecific(stream_bkey); |
1203 | 23.5k | } else { |
1204 | 0 | return (LogStream**)pthread_getspecific(stream_pkey); |
1205 | 0 | } |
1206 | 23.5k | } |
1207 | | |
1208 | 23.5k | static LogStream** get_or_new_tls_stream_array() { |
1209 | 23.5k | LogStream** a = get_tls_stream_array(); |
1210 | 23.5k | if (a == NULL) { |
1211 | 5 | a = new LogStream*[LOG_NUM_SEVERITIES + 1]; |
1212 | 5 | memset(a, 0, sizeof(LogStream*) * (LOG_NUM_SEVERITIES + 1)); |
1213 | 5 | if (is_bthread_linked()) { |
1214 | 5 | bthread_setspecific(stream_bkey, a); |
1215 | 5 | } else { |
1216 | 0 | pthread_setspecific(stream_pkey, a); |
1217 | 0 | } |
1218 | 5 | } |
1219 | 23.5k | return a; |
1220 | 23.5k | } |
1221 | | |
1222 | | inline LogStream* CreateLogStream(const LogChar* file, |
1223 | | int line, |
1224 | | const LogChar* func, |
1225 | 23.5k | LogSeverity severity) { |
1226 | 23.5k | int slot = 0; |
1227 | 23.5k | if (severity >= 0) { |
1228 | 23.5k | DCHECK_LT(severity, LOG_NUM_SEVERITIES); |
1229 | 23.5k | slot = severity + 1; |
1230 | 23.5k | } // else vlog |
1231 | 23.5k | LogStream** stream_array = get_or_new_tls_stream_array(); |
1232 | 23.5k | LogStream* stream = stream_array[slot]; |
1233 | 23.5k | if (stream == NULL) { |
1234 | 9 | stream = new LogStream; |
1235 | 9 | stream_array[slot] = stream; |
1236 | 9 | } |
1237 | 23.5k | if (stream->empty()) { |
1238 | 23.5k | stream->SetPosition(file, line, func, severity); |
1239 | 23.5k | } |
1240 | 23.5k | return stream; |
1241 | 23.5k | } |
1242 | | |
1243 | | inline LogStream* CreateLogStream(const LogChar* file, |
1244 | | int line, |
1245 | 0 | LogSeverity severity) { |
1246 | 0 | return CreateLogStream(file, line, "", severity); |
1247 | 0 | } |
1248 | | |
1249 | 23.5k | inline void DestroyLogStream(LogStream* stream) { |
1250 | 23.5k | if (stream != NULL) { |
1251 | 23.5k | stream->Flush(); |
1252 | 23.5k | } |
1253 | 23.5k | } |
1254 | | |
1255 | | #else |
1256 | | |
1257 | | inline LogStream* CreateLogStream(const LogChar* file, int line, |
1258 | | LogSeverity severity) { |
1259 | | return CreateLogStream(file, line, "", severity); |
1260 | | } |
1261 | | |
1262 | | |
1263 | | inline LogStream* CreateLogStream(const LogChar* file, int line, |
1264 | | const LogChar* func, |
1265 | | LogSeverity severity) { |
1266 | | LogStream* stream = new LogStream; |
1267 | | stream->SetPosition(file, line, func, severity); |
1268 | | return stream; |
1269 | | } |
1270 | | |
1271 | | inline void DestroyLogStream(LogStream* stream) { |
1272 | | delete stream; |
1273 | | } |
1274 | | |
1275 | | #endif // __GNUC__ |
1276 | | |
1277 | | class DefaultLogSink : public LogSink { |
1278 | | public: |
1279 | 23.5k | static DefaultLogSink* GetInstance() { |
1280 | 23.5k | return Singleton<DefaultLogSink, |
1281 | 23.5k | LeakySingletonTraits<DefaultLogSink> >::get(); |
1282 | 23.5k | } |
1283 | | |
1284 | | bool OnLogMessage(int severity, const char* file, int line, |
1285 | 23.5k | const butil::StringPiece& content) override { |
1286 | 23.5k | return OnLogMessage(severity, file, line, "", content); |
1287 | 23.5k | } |
1288 | | |
1289 | | bool OnLogMessage(int severity, const char* file, |
1290 | | int line, const char* func, |
1291 | 23.5k | const butil::StringPiece& content) override { |
1292 | 23.5k | std::string log; |
1293 | 23.5k | if ((logging_destination & LOG_TO_SYSTEM_DEBUG_LOG) != 0 || |
1294 | 23.5k | severity >= kAlwaysPrintErrorLevel) { |
1295 | 23.5k | log = LogInfoToLogStr(severity, file, line, func, content); |
1296 | | // When we're only outputting to a log file, above a certain log level, we |
1297 | | // should still output to stderr so that we can better detect and diagnose |
1298 | | // problems with unit tests, especially on the buildbots. |
1299 | 23.5k | fwrite(log.data(), log.size(), 1, stderr); |
1300 | 23.5k | fflush(stderr); |
1301 | 23.5k | } |
1302 | | // write to log file |
1303 | 23.5k | if ((logging_destination & LOG_TO_FILE) != 0) { |
1304 | 0 | if ((FLAGS_crash_on_fatal_log && severity == BLOG_FATAL) || |
1305 | 0 | !FLAGS_async_log) { |
1306 | 0 | if (log.empty()) { |
1307 | 0 | log = LogInfoToLogStr(severity, file, line, func, content); |
1308 | 0 | } |
1309 | 0 | Log2File(log); |
1310 | 0 | } else { |
1311 | 0 | LogInfo info; |
1312 | 0 | if (log.empty()) { |
1313 | 0 | info.severity = severity; |
1314 | 0 | info.timestamp = GetTimestamp(); |
1315 | 0 | info.file = file; |
1316 | 0 | info.func = func; |
1317 | 0 | info.line = line; |
1318 | 0 | info.content = content.as_string(); |
1319 | 0 | info.raw = true; |
1320 | 0 | } else { |
1321 | 0 | info.content = std::move(log); |
1322 | 0 | info.raw = false; |
1323 | 0 | } |
1324 | 0 | AsyncLogger::GetInstance()->Log(std::move(info)); |
1325 | 0 | } |
1326 | 0 | } |
1327 | 23.5k | return true; |
1328 | 23.5k | } |
1329 | | private: |
1330 | 5 | DefaultLogSink() = default; |
1331 | | ~DefaultLogSink() override = default; |
1332 | | friend struct DefaultSingletonTraits<DefaultLogSink>; |
1333 | | }; |
1334 | | |
1335 | 23.5k | void LogStream::FlushWithoutReset() { |
1336 | 23.5k | if (empty()) { |
1337 | | // Nothing to flush. |
1338 | 0 | return; |
1339 | 0 | } |
1340 | | |
1341 | 23.5k | #if !defined(OS_NACL) && !defined(__UCLIBC__) |
1342 | 23.5k | if ((FLAGS_print_stack_on_check && _is_check && _severity == BLOG_FATAL) || _backtrace) { |
1343 | | // Include a stack trace on a fatal. |
1344 | 137 | butil::debug::StackTrace trace; |
1345 | 137 | size_t count = 0; |
1346 | 137 | const void* const* addrs = trace.Addresses(&count); |
1347 | | |
1348 | 137 | *this << std::endl; // Newline to separate from log message. |
1349 | 137 | if (count > 3) { |
1350 | | // Remove top 3 frames which are useless to users. |
1351 | | // #2 may be ~LogStream |
1352 | | // #0 0x00000059ccae butil::debug::StackTrace::StackTrace() |
1353 | | // #1 0x0000005947c7 logging::LogStream::FlushWithoutReset() |
1354 | | // #2 0x000000594b88 logging::LogMessage::~LogMessage() |
1355 | 137 | butil::debug::StackTrace trace_stripped(addrs + 3, count - 3); |
1356 | 137 | trace_stripped.OutputToStream(this); |
1357 | 137 | } else { |
1358 | 0 | trace.OutputToStream(this); |
1359 | 0 | } |
1360 | 137 | } |
1361 | 23.5k | #endif |
1362 | | // End the data with zero because sink is likely to assume this. |
1363 | 23.5k | *this << std::ends; |
1364 | | // Move back one step because we don't want to count the zero. |
1365 | 23.5k | pbump(-1); |
1366 | | |
1367 | | // Give any logsink first dibs on the message. |
1368 | | #ifdef BAIDU_INTERNAL |
1369 | | // If the logsink fails and it's not comlog, try comlog. stderr on last try. |
1370 | | bool tried_comlog = false; |
1371 | | #endif |
1372 | 23.5k | bool tried_default = false; |
1373 | 23.5k | { |
1374 | 23.5k | DoublyBufferedLogSink::ScopedPtr ptr; |
1375 | 23.5k | if (DoublyBufferedLogSink::GetInstance()->Read(&ptr) == 0 && |
1376 | 23.5k | (*ptr) != NULL) { |
1377 | 0 | bool result = false; |
1378 | 0 | if (FLAGS_log_func_name) { |
1379 | 0 | result = (*ptr)->OnLogMessage(_severity, _file, _line, |
1380 | 0 | _func, content()); |
1381 | 0 | } else { |
1382 | 0 | result = (*ptr)->OnLogMessage(_severity, _file, |
1383 | 0 | _line, content()); |
1384 | 0 | } |
1385 | 0 | if (result) { |
1386 | 0 | goto FINISH_LOGGING; |
1387 | 0 | } |
1388 | | #ifdef BAIDU_INTERNAL |
1389 | | tried_comlog = (*ptr == ComlogSink::GetInstance()); |
1390 | | #endif |
1391 | 0 | tried_default = (*ptr == DefaultLogSink::GetInstance()); |
1392 | 0 | } |
1393 | 23.5k | } |
1394 | | |
1395 | | #ifdef BAIDU_INTERNAL |
1396 | | if (!tried_comlog) { |
1397 | | if (ComlogSink::GetInstance()->OnLogMessage( |
1398 | | _severity, _file, _line, _func, content())) { |
1399 | | goto FINISH_LOGGING; |
1400 | | } |
1401 | | } |
1402 | | #endif |
1403 | 23.5k | if (!tried_default) { |
1404 | 23.5k | if (FLAGS_log_func_name) { |
1405 | 0 | DefaultLogSink::GetInstance()->OnLogMessage( |
1406 | 0 | _severity, _file, _line, _func, content()); |
1407 | 23.5k | } else { |
1408 | 23.5k | DefaultLogSink::GetInstance()->OnLogMessage( |
1409 | 23.5k | _severity, _file, _line, content()); |
1410 | 23.5k | } |
1411 | 23.5k | } |
1412 | | |
1413 | 23.5k | FINISH_LOGGING: |
1414 | 23.5k | if (FLAGS_crash_on_fatal_log && _severity == BLOG_FATAL) { |
1415 | | // Ensure the first characters of the string are on the stack so they |
1416 | | // are contained in minidumps for diagnostic purposes. |
1417 | 0 | butil::StringPiece str = content(); |
1418 | 0 | char str_stack[1024]; |
1419 | 0 | str.copy(str_stack, arraysize(str_stack)); |
1420 | 0 | butil::debug::Alias(str_stack); |
1421 | |
|
1422 | 0 | if (log_assert_handler) { |
1423 | | // Make a copy of the string for the handler out of paranoia. |
1424 | 0 | log_assert_handler(str.as_string()); |
1425 | 0 | } else { |
1426 | | // Don't use the string with the newline, get a fresh version to send to |
1427 | | // the debug message process. We also don't display assertions to the |
1428 | | // user in release mode. The enduser can't do anything with this |
1429 | | // information, and displaying message boxes when the application is |
1430 | | // hosed can cause additional problems. |
1431 | 0 | #ifndef NDEBUG |
1432 | 0 | DisplayDebugMessageInDialog(str.as_string()); |
1433 | 0 | #endif |
1434 | | // Crash the process to generate a dump. |
1435 | 0 | butil::debug::BreakDebugger(); |
1436 | 0 | } |
1437 | 0 | } |
1438 | 23.5k | } |
1439 | | |
1440 | | LogMessage::LogMessage(const char* file, int line, LogSeverity severity) |
1441 | 0 | : LogMessage(file, line, "", severity) {} |
1442 | | |
1443 | | LogMessage::LogMessage(const char* file, int line, |
1444 | 23.5k | const char* func, LogSeverity severity) { |
1445 | 23.5k | _stream = CreateLogStream(file, line, func, severity); |
1446 | 23.5k | } |
1447 | | |
1448 | | LogMessage::LogMessage(const char* file, int line, std::string* result) |
1449 | 0 | : LogMessage(file, line, "", result) {} |
1450 | | |
1451 | | LogMessage::LogMessage(const char* file, int line, |
1452 | 0 | const char* func, std::string* result) { |
1453 | 0 | _stream = CreateLogStream(file, line, func, BLOG_FATAL); |
1454 | 0 | *_stream << "Check failed: " << *result; |
1455 | 0 | delete result; |
1456 | 0 | } |
1457 | | |
1458 | | LogMessage::LogMessage(const char* file, int line, LogSeverity severity, |
1459 | | std::string* result) |
1460 | 0 | : LogMessage(file, line, "", severity, result) {} |
1461 | | |
1462 | | LogMessage::LogMessage(const char* file, int line, const char* func, |
1463 | 0 | LogSeverity severity, std::string* result) { |
1464 | 0 | _stream = CreateLogStream(file, line, func, severity); |
1465 | 0 | *_stream << "Check failed: " << *result; |
1466 | 0 | delete result; |
1467 | 0 | } |
1468 | | |
1469 | 23.5k | LogMessage::~LogMessage() { |
1470 | 23.5k | DestroyLogStream(_stream); |
1471 | 23.5k | } |
1472 | | |
1473 | | #if defined(OS_WIN) |
1474 | | // This has already been defined in the header, but defining it again as DWORD |
1475 | | // ensures that the type used in the header is equivalent to DWORD. If not, |
1476 | | // the redefinition is a compile error. |
1477 | | typedef DWORD SystemErrorCode; |
1478 | | #endif |
1479 | | |
1480 | 23.5k | SystemErrorCode GetLastSystemErrorCode() { |
1481 | | #if defined(OS_WIN) |
1482 | | return ::GetLastError(); |
1483 | | #elif defined(OS_POSIX) |
1484 | | return errno; |
1485 | | #else |
1486 | | #error Not implemented |
1487 | | #endif |
1488 | 23.5k | } |
1489 | | |
1490 | 23.5k | void SetLastSystemErrorCode(SystemErrorCode err) { |
1491 | | #if defined(OS_WIN) |
1492 | | ::SetLastError(err); |
1493 | | #elif defined(OS_POSIX) |
1494 | | errno = err; |
1495 | | #else |
1496 | | #error Not implemented |
1497 | | #endif |
1498 | 23.5k | } |
1499 | | |
1500 | | #if defined(OS_WIN) |
1501 | | BUTIL_EXPORT std::string SystemErrorCodeToString(SystemErrorCode error_code) { |
1502 | | const int error_message_buffer_size = 256; |
1503 | | char msgbuf[error_message_buffer_size]; |
1504 | | DWORD flags = FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS; |
1505 | | DWORD len = FormatMessageA(flags, NULL, error_code, 0, msgbuf, |
1506 | | arraysize(msgbuf), NULL); |
1507 | | if (len) { |
1508 | | // Messages returned by system end with line breaks. |
1509 | | return butil::CollapseWhitespaceASCII(msgbuf, true) + |
1510 | | butil::StringPrintf(" (0x%X)", error_code); |
1511 | | } |
1512 | | return butil::StringPrintf("Error (0x%X) while retrieving error. (0x%X)", |
1513 | | GetLastError(), error_code); |
1514 | | } |
1515 | | #elif defined(OS_POSIX) |
1516 | 0 | BUTIL_EXPORT std::string SystemErrorCodeToString(SystemErrorCode error_code) { |
1517 | 0 | return berror(error_code); |
1518 | 0 | } |
1519 | | #else |
1520 | | #error Not implemented |
1521 | | #endif |
1522 | | |
1523 | | |
1524 | | #if defined(OS_WIN) |
1525 | | Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file, |
1526 | | int line, |
1527 | | LogSeverity severity, |
1528 | | SystemErrorCode err) |
1529 | | : Win32ErrorLogMessage(file, line, "", severity, err) { |
1530 | | } |
1531 | | |
1532 | | Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file, |
1533 | | int line, |
1534 | | const char* func, |
1535 | | LogSeverity severity, |
1536 | | SystemErrorCode err) |
1537 | | : err_(err) |
1538 | | , log_message_(file, line, func, severity) { |
1539 | | } |
1540 | | |
1541 | | Win32ErrorLogMessage::~Win32ErrorLogMessage() { |
1542 | | stream() << ": " << SystemErrorCodeToString(err_); |
1543 | | // We're about to crash (CHECK). Put |err_| on the stack (by placing it in a |
1544 | | // field) and use Alias in hopes that it makes it into crash dumps. |
1545 | | DWORD last_error = err_; |
1546 | | butil::debug::Alias(&last_error); |
1547 | | } |
1548 | | #elif defined(OS_POSIX) |
1549 | | ErrnoLogMessage::ErrnoLogMessage(const char* file, |
1550 | | int line, |
1551 | | LogSeverity severity, |
1552 | | SystemErrorCode err) |
1553 | 0 | : ErrnoLogMessage(file, line, "", severity, err) {} |
1554 | | |
1555 | | ErrnoLogMessage::ErrnoLogMessage(const char* file, |
1556 | | int line, |
1557 | | const char* func, |
1558 | | LogSeverity severity, |
1559 | | SystemErrorCode err) |
1560 | 0 | : err_(err) |
1561 | 0 | , log_message_(file, line, func, severity) {} |
1562 | | |
1563 | 0 | ErrnoLogMessage::~ErrnoLogMessage() { |
1564 | 0 | stream() << ": " << SystemErrorCodeToString(err_); |
1565 | 0 | } |
1566 | | #endif // OS_WIN |
1567 | | |
1568 | 0 | void CloseLogFile() { |
1569 | 0 | LoggingLock logging_lock; |
1570 | 0 | CloseLogFileUnlocked(); |
1571 | 0 | } |
1572 | | |
1573 | 0 | void RawLog(int level, const char* message) { |
1574 | 0 | if (level >= FLAGS_minloglevel) { |
1575 | 0 | size_t bytes_written = 0; |
1576 | 0 | const size_t message_len = strlen(message); |
1577 | 0 | int rv; |
1578 | 0 | while (bytes_written < message_len) { |
1579 | 0 | rv = HANDLE_EINTR( |
1580 | 0 | write(STDERR_FILENO, message + bytes_written, |
1581 | 0 | message_len - bytes_written)); |
1582 | 0 | if (rv < 0) { |
1583 | | // Give up, nothing we can do now. |
1584 | 0 | break; |
1585 | 0 | } |
1586 | 0 | bytes_written += rv; |
1587 | 0 | } |
1588 | |
|
1589 | 0 | if (message_len > 0 && message[message_len - 1] != '\n') { |
1590 | 0 | do { |
1591 | 0 | rv = HANDLE_EINTR(write(STDERR_FILENO, "\n", 1)); |
1592 | 0 | if (rv < 0) { |
1593 | | // Give up, nothing we can do now. |
1594 | 0 | break; |
1595 | 0 | } |
1596 | 0 | } while (rv != 1); |
1597 | 0 | } |
1598 | 0 | } |
1599 | | |
1600 | 0 | if (FLAGS_crash_on_fatal_log && level == BLOG_FATAL) |
1601 | 0 | butil::debug::BreakDebugger(); |
1602 | 0 | } |
1603 | | |
1604 | | // This was defined at the beginning of this file. |
1605 | | #undef write |
1606 | | |
1607 | | #if defined(OS_WIN) |
1608 | | std::wstring GetLogFileFullPath() { |
1609 | | if (log_file_name) |
1610 | | return *log_file_name; |
1611 | | return std::wstring(); |
1612 | | } |
1613 | | #endif |
1614 | | |
1615 | | |
1616 | | // ----------- VLOG stuff ----------------- |
1617 | | struct VLogSite; |
1618 | | struct VModuleList; |
1619 | | |
1620 | | extern const int VLOG_UNINITIALIZED = std::numeric_limits<int>::max(); |
1621 | | |
1622 | | static pthread_mutex_t vlog_site_list_mutex = PTHREAD_MUTEX_INITIALIZER; |
1623 | | static VLogSite* vlog_site_list = NULL; |
1624 | | static VModuleList* vmodule_list = NULL; |
1625 | | |
1626 | | static pthread_mutex_t reset_vmodule_and_v_mutex = PTHREAD_MUTEX_INITIALIZER; |
1627 | | |
1628 | | static const int64_t DELAY_DELETION_SEC = 10; |
1629 | | static std::deque<std::pair<VModuleList*, int64_t> >* |
1630 | | deleting_vmodule_list = NULL; |
1631 | | |
1632 | | struct VLogSite { |
1633 | | VLogSite(const char* filename, int required_v, int line_no) |
1634 | 3 | : _next(0), _v(0), _required_v(required_v), _line_no(line_no) { |
1635 | | // Remove dirname/extname. |
1636 | 3 | butil::StringPiece s(filename); |
1637 | 3 | size_t pos = s.find_last_of("./"); |
1638 | 3 | if (pos != butil::StringPiece::npos) { |
1639 | 3 | if (s[pos] == '.') { |
1640 | 3 | s.remove_suffix(s.size() - pos); |
1641 | 3 | _full_module.assign(s.data(), s.size()); |
1642 | 3 | size_t pos2 = s.find_last_of('/'); |
1643 | 3 | if (pos2 != butil::StringPiece::npos) { |
1644 | 3 | s.remove_prefix(pos2 + 1); |
1645 | 3 | } |
1646 | 3 | } else { |
1647 | 0 | _full_module.assign(s.data(), s.size()); |
1648 | 0 | s.remove_prefix(pos + 1); |
1649 | 0 | } |
1650 | 3 | } // else keep _full_module empty when it equals _module |
1651 | 3 | _module.assign(s.data(), s.size()); |
1652 | 3 | std::transform(_module.begin(), _module.end(), |
1653 | 3 | _module.begin(), ::tolower); |
1654 | 3 | if (!_full_module.empty()) { |
1655 | 3 | std::transform(_full_module.begin(), _full_module.end(), |
1656 | 3 | _full_module.begin(), ::tolower); |
1657 | 3 | } |
1658 | 3 | } |
1659 | | |
1660 | | // The consume/release fence makes the iteration outside lock see |
1661 | | // newly added VLogSite correctly. |
1662 | 0 | VLogSite* next() { return (VLogSite*)butil::subtle::Acquire_Load(&_next); } |
1663 | | const VLogSite* next() const |
1664 | 0 | { return (VLogSite*)butil::subtle::Acquire_Load(&_next); } |
1665 | | void set_next(VLogSite* next) |
1666 | 3 | { butil::subtle::Release_Store(&_next, (butil::subtle::AtomicWord)next); } |
1667 | | |
1668 | 0 | int v() const { return _v; } |
1669 | 9 | int& v() { return _v; } |
1670 | | |
1671 | 0 | int required_v() const { return _required_v; } |
1672 | 0 | int line_no() const { return _line_no; } |
1673 | | |
1674 | 0 | const std::string& module() const { return _module; } |
1675 | 0 | const std::string& full_module() const { return _full_module; } |
1676 | | |
1677 | | private: |
1678 | | // Next site in the list. NULL means no next. |
1679 | | butil::subtle::AtomicWord _next; |
1680 | | |
1681 | | // --vmodule > --v |
1682 | | int _v; |
1683 | | |
1684 | | // vlog is on iff _v >= _required_v |
1685 | | int _required_v; |
1686 | | |
1687 | | // line nubmer of the vlog. |
1688 | | int _line_no; |
1689 | | |
1690 | | // Lowered, dirname & extname removed. |
1691 | | std::string _module; |
1692 | | // Lowered, extname removed. Empty when it equals to _module. |
1693 | | std::string _full_module; |
1694 | | }; |
1695 | | |
1696 | | // Written by Jack Handy |
1697 | | // <A href="mailto:jakkhandy@hotmail.com">jakkhandy@hotmail.com</A> |
1698 | 0 | bool wildcmp(const char* wild, const char* str) { |
1699 | 0 | const char* cp = NULL; |
1700 | 0 | const char* mp = NULL; |
1701 | |
|
1702 | 0 | while (*str && *wild != '*') { |
1703 | 0 | if (*wild != *str && *wild != '?') { |
1704 | 0 | return false; |
1705 | 0 | } |
1706 | 0 | ++wild; |
1707 | 0 | ++str; |
1708 | 0 | } |
1709 | | |
1710 | 0 | while (*str) { |
1711 | 0 | if (*wild == '*') { |
1712 | 0 | if (!*++wild) { |
1713 | 0 | return true; |
1714 | 0 | } |
1715 | 0 | mp = wild; |
1716 | 0 | cp = str+1; |
1717 | 0 | } else if (*wild == *str || *wild == '?') { |
1718 | 0 | ++wild; |
1719 | 0 | ++str; |
1720 | 0 | } else { |
1721 | 0 | wild = mp; |
1722 | 0 | str = cp++; |
1723 | 0 | } |
1724 | 0 | } |
1725 | | |
1726 | 0 | while (*wild == '*') { |
1727 | 0 | ++wild; |
1728 | 0 | } |
1729 | 0 | return !*wild; |
1730 | 0 | } |
1731 | | |
1732 | | struct VModuleList { |
1733 | 0 | VModuleList() {} |
1734 | | |
1735 | 0 | int init(const char* vmodules) { |
1736 | 0 | _exact_names.clear(); |
1737 | 0 | _wild_names.clear(); |
1738 | | |
1739 | 0 | for (butil::StringSplitter sp(vmodules, ','); sp; ++sp) { |
1740 | 0 | int verbose_level = std::numeric_limits<int>::max(); |
1741 | 0 | size_t off = 0; |
1742 | 0 | for (; off < sp.length() && sp.field()[off] != '='; ++off) {} |
1743 | 0 | if (off + 1 < sp.length()) { |
1744 | 0 | verbose_level = strtol(sp.field() + off + 1, NULL, 10); |
1745 | | |
1746 | 0 | } |
1747 | 0 | const char* name_begin = sp.field(); |
1748 | 0 | const char* name_end = sp.field() + off - 1; |
1749 | 0 | for (; isspace(*name_begin) && name_begin < sp.field() + off; |
1750 | 0 | ++name_begin) {} |
1751 | 0 | for (; isspace(*name_end) && name_end >= sp.field(); --name_end) {} |
1752 | | |
1753 | 0 | if (name_begin > name_end) { // only has spaces |
1754 | 0 | continue; |
1755 | 0 | } |
1756 | 0 | std::string name(name_begin, name_end - name_begin + 1); |
1757 | 0 | std::transform(name.begin(), name.end(), name.begin(), ::tolower); |
1758 | 0 | if (name.find_first_of("*?") == std::string::npos) { |
1759 | 0 | _exact_names[name] = verbose_level; |
1760 | 0 | } else { |
1761 | 0 | _wild_names.emplace_back(name, verbose_level); |
1762 | 0 | } |
1763 | 0 | } |
1764 | | // Reverse _wild_names so that latter wild cards override former ones. |
1765 | 0 | if (!_wild_names.empty()) { |
1766 | 0 | std::reverse(_wild_names.begin(), _wild_names.end()); |
1767 | 0 | } |
1768 | 0 | return 0; |
1769 | 0 | } |
1770 | | |
1771 | | bool find_verbose_level(const std::string& module, |
1772 | 0 | const std::string& full_module, int* v) const { |
1773 | 0 | if (!_exact_names.empty()) { |
1774 | 0 | std::map<std::string, int>::const_iterator |
1775 | 0 | it = _exact_names.find(module); |
1776 | 0 | if (it != _exact_names.end()) { |
1777 | 0 | *v = it->second; |
1778 | 0 | return true; |
1779 | 0 | } |
1780 | 0 | if (!full_module.empty()) { |
1781 | 0 | it = _exact_names.find(full_module); |
1782 | 0 | if (it != _exact_names.end()) { |
1783 | 0 | *v = it->second; |
1784 | 0 | return true; |
1785 | 0 | } |
1786 | 0 | } |
1787 | 0 | } |
1788 | | |
1789 | 0 | for (size_t i = 0; i < _wild_names.size(); ++i) { |
1790 | 0 | if (wildcmp(_wild_names[i].first.c_str(), module.c_str())) { |
1791 | 0 | *v = _wild_names[i].second; |
1792 | 0 | return true; |
1793 | 0 | } |
1794 | 0 | if (!full_module.empty() && |
1795 | 0 | wildcmp(_wild_names[i].first.c_str(), full_module.c_str())) { |
1796 | 0 | *v = _wild_names[i].second; |
1797 | 0 | return true; |
1798 | 0 | } |
1799 | 0 | } |
1800 | 0 | return false; |
1801 | 0 | } |
1802 | | |
1803 | 0 | void print(std::ostream& os) const { |
1804 | 0 | os << "exact:"; |
1805 | 0 | for (std::map<std::string, int>::const_iterator |
1806 | 0 | it = _exact_names.begin(); it != _exact_names.end(); ++it) { |
1807 | 0 | os << ' ' << it->first << '=' << it->second; |
1808 | 0 | } |
1809 | 0 | os << ", wild:"; |
1810 | 0 | for (size_t i = 0; i < _wild_names.size(); ++i) { |
1811 | 0 | os << ' ' << _wild_names[i].first << '=' << _wild_names[i].second; |
1812 | 0 | } |
1813 | 0 | } |
1814 | | |
1815 | | private: |
1816 | | std::map<std::string, int> _exact_names; |
1817 | | std::vector<std::pair<std::string, int> > _wild_names; |
1818 | | }; |
1819 | | |
1820 | | // [ The idea ] |
1821 | | // Each callsite creates a VLogSite and inserts the site into singly-linked |
1822 | | // vlog_site_list. To keep the critical area small, we use optimistic |
1823 | | // locking : Assign local site w/o locking, then insert the site into |
1824 | | // global list w/ locking, if local_module_list != global_vmodule_list or |
1825 | | // local_default_v != FLAGS_v, repeat the assigment. |
1826 | | // An important property of vlog_site_list is that: It does not remove sites. |
1827 | | // When we need to iterate the list, we don't have to hold the lock. What we |
1828 | | // do is to get the head of the list inside lock and iterate the list w/o |
1829 | | // lock. If new sites is inserted during the iteration, it should see and |
1830 | | // use the updated vmodule_list and FLAGS_v, nothing will be missed. |
1831 | | |
1832 | | static int vlog_site_list_add(VLogSite* site, |
1833 | | VModuleList** expected_module_list, |
1834 | 3 | int* expected_default_v) { |
1835 | 3 | BAIDU_SCOPED_LOCK(vlog_site_list_mutex); |
1836 | 3 | if (vmodule_list != *expected_module_list) { |
1837 | 0 | *expected_module_list = vmodule_list; |
1838 | 0 | return -1; |
1839 | 0 | } |
1840 | 3 | if (*expected_default_v != FLAGS_v) { |
1841 | 0 | *expected_default_v = FLAGS_v; |
1842 | 0 | return -1; |
1843 | 0 | } |
1844 | 3 | site->set_next(vlog_site_list); |
1845 | 3 | vlog_site_list = site; |
1846 | 3 | return 0; |
1847 | 3 | } |
1848 | | |
1849 | | bool add_vlog_site(const int** v, const char* filename, int line_no, |
1850 | 3 | int required_v) { |
1851 | 3 | VLogSite* site = new (std::nothrow) VLogSite(filename, required_v, line_no); |
1852 | 3 | if (site == NULL) { |
1853 | 0 | return false; |
1854 | 0 | } |
1855 | 3 | VModuleList* module_list = vmodule_list; |
1856 | 3 | int default_v = FLAGS_v; |
1857 | 3 | do { |
1858 | 3 | site->v() = default_v; |
1859 | 3 | if (module_list) { |
1860 | 0 | module_list->find_verbose_level( |
1861 | 0 | site->module(), site->full_module(), &site->v()); |
1862 | 0 | } |
1863 | 3 | } while (vlog_site_list_add(site, &module_list, &default_v) != 0); |
1864 | 3 | *v = &site->v(); |
1865 | 3 | return site->v() >= required_v; |
1866 | 3 | } |
1867 | | |
1868 | 0 | void print_vlog_sites(VLogSitePrinter* printer) { |
1869 | 0 | VLogSite* head = NULL; |
1870 | 0 | { |
1871 | 0 | BAIDU_SCOPED_LOCK(vlog_site_list_mutex); |
1872 | 0 | head = vlog_site_list; |
1873 | 0 | } |
1874 | 0 | VLogSitePrinter::Site site; |
1875 | 0 | for (const VLogSite* p = head; p; p = p->next()) { |
1876 | 0 | site.current_verbose_level = p->v(); |
1877 | 0 | site.required_verbose_level = p->required_v(); |
1878 | 0 | site.line_no = p->line_no(); |
1879 | 0 | site.full_module = p->full_module(); |
1880 | 0 | printer->print(site); |
1881 | 0 | } |
1882 | 0 | } |
1883 | | |
1884 | | // [Thread-safe] Reset FLAGS_vmodule. |
1885 | 0 | static int on_reset_vmodule(const char* vmodule) { |
1886 | | // resetting must be serialized. |
1887 | 0 | BAIDU_SCOPED_LOCK(reset_vmodule_and_v_mutex); |
1888 | | |
1889 | 0 | VModuleList* module_list = new (std::nothrow) VModuleList; |
1890 | 0 | if (NULL == module_list) { |
1891 | 0 | LOG(FATAL) << "Fail to new VModuleList"; |
1892 | 0 | return -1; |
1893 | 0 | } |
1894 | 0 | if (module_list->init(vmodule) != 0) { |
1895 | 0 | delete module_list; |
1896 | 0 | LOG(FATAL) << "Fail to init VModuleList"; |
1897 | 0 | return -1; |
1898 | 0 | } |
1899 | | |
1900 | 0 | VModuleList* old_module_list = NULL; |
1901 | 0 | VLogSite* old_vlog_site_list = NULL; |
1902 | 0 | { |
1903 | 0 | { |
1904 | 0 | BAIDU_SCOPED_LOCK(vlog_site_list_mutex); |
1905 | 0 | old_module_list = vmodule_list; |
1906 | 0 | vmodule_list = module_list; |
1907 | 0 | old_vlog_site_list = vlog_site_list; |
1908 | 0 | } |
1909 | 0 | for (VLogSite* p = old_vlog_site_list; p; p = p->next()) { |
1910 | 0 | p->v() = FLAGS_v; |
1911 | 0 | module_list->find_verbose_level( |
1912 | 0 | p->module(), p->full_module(), &p->v()); |
1913 | 0 | } |
1914 | 0 | } |
1915 | | |
1916 | 0 | if (old_module_list) { |
1917 | | //delay the deletion. |
1918 | 0 | if (NULL == deleting_vmodule_list) { |
1919 | 0 | deleting_vmodule_list = |
1920 | 0 | new std::deque<std::pair<VModuleList*, int64_t> >; |
1921 | 0 | } |
1922 | 0 | deleting_vmodule_list->push_back( |
1923 | 0 | std::make_pair(old_module_list, |
1924 | 0 | butil::gettimeofday_us() + DELAY_DELETION_SEC * 1000000L)); |
1925 | 0 | while (!deleting_vmodule_list->empty() && |
1926 | 0 | deleting_vmodule_list->front().second <= butil::gettimeofday_us()) { |
1927 | 0 | delete deleting_vmodule_list->front().first; |
1928 | 0 | deleting_vmodule_list->pop_front(); |
1929 | 0 | } |
1930 | 0 | } |
1931 | 0 | return 0; |
1932 | 0 | } |
1933 | | |
1934 | 0 | static bool validate_vmodule(const char*, const std::string& vmodule) { |
1935 | 0 | return on_reset_vmodule(vmodule.c_str()) == 0; |
1936 | 0 | } |
1937 | | |
1938 | | const bool ALLOW_UNUSED validate_vmodule_dummy = GFLAGS_NAMESPACE::RegisterFlagValidator( |
1939 | | &FLAGS_vmodule, &validate_vmodule); |
1940 | | |
1941 | | // [Thread-safe] Reset FLAGS_v. |
1942 | 0 | static void on_reset_verbose(int default_v) { |
1943 | 0 | VModuleList* cur_module_list = NULL; |
1944 | 0 | VLogSite* cur_vlog_site_list = NULL; |
1945 | 0 | { |
1946 | | // resetting must be serialized. |
1947 | 0 | BAIDU_SCOPED_LOCK(reset_vmodule_and_v_mutex); |
1948 | 0 | { |
1949 | 0 | BAIDU_SCOPED_LOCK(vlog_site_list_mutex); |
1950 | 0 | cur_module_list = vmodule_list; |
1951 | 0 | cur_vlog_site_list = vlog_site_list; |
1952 | 0 | } |
1953 | 0 | for (VLogSite* p = cur_vlog_site_list; p; p = p->next()) { |
1954 | 0 | p->v() = default_v; |
1955 | 0 | if (cur_module_list) { |
1956 | 0 | cur_module_list->find_verbose_level( |
1957 | 0 | p->module(), p->full_module(), &p->v()); |
1958 | 0 | } |
1959 | 0 | } |
1960 | 0 | } |
1961 | 0 | } |
1962 | | |
1963 | 0 | static bool validate_v(const char*, int32_t v) { |
1964 | 0 | on_reset_verbose(v); |
1965 | 0 | return true; |
1966 | 0 | } |
1967 | | BUTIL_VALIDATE_GFLAG(v, validate_v); |
1968 | | |
1969 | | } // namespace logging |
1970 | | |
1971 | 0 | std::ostream& operator<<(std::ostream& out, const wchar_t* wstr) { |
1972 | 0 | return out << butil::WideToUTF8(std::wstring(wstr)); |
1973 | 0 | } |
1974 | | |
1975 | | #endif // BRPC_WITH_GLOG |