/* * Copyright (C) 2019 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include "perfetto/base/logging.h" #include #include #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) #include // For isatty() #endif #include #include #include "perfetto/base/build_config.h" #include "perfetto/base/time.h" #include "perfetto/ext/base/crash_keys.h" #include "perfetto/ext/base/string_utils.h" #include "perfetto/ext/base/string_view.h" #include "src/base/log_ring_buffer.h" #if PERFETTO_ENABLE_LOG_RING_BUFFER() && PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID) #include #endif namespace perfetto { namespace base { namespace { const char kReset[] = "\x1b[0m"; const char kDefault[] = "\x1b[39m"; const char kDim[] = "\x1b[2m"; const char kRed[] = "\x1b[31m"; const char kBoldGreen[] = "\x1b[1m\x1b[32m"; const char kLightGray[] = "\x1b[90m"; std::atomic g_log_callback{}; #if PERFETTO_BUILDFLAG(PERFETTO_STDERR_CRASH_DUMP) // __attribute__((constructor)) causes a static initializer that automagically // early runs this function before the main(). void PERFETTO_EXPORT_COMPONENT __attribute__((constructor)) InitDebugCrashReporter() { // This function is defined in debug_crash_stack_trace.cc. // The dynamic initializer is in logging.cc because logging.cc is included // in virtually any target that depends on base. Having it in // debug_crash_stack_trace.cc would require figuring out -Wl,whole-archive // which is not worth it. EnableStacktraceOnCrashForDebug(); } #endif #if PERFETTO_ENABLE_LOG_RING_BUFFER() LogRingBuffer g_log_ring_buffer{}; // This is global to avoid allocating memory or growing too much the stack // in MaybeSerializeLastLogsForCrashReporting(), which is called from // arbitrary code paths hitting PERFETTO_CHECK()/FATAL(). char g_crash_buf[kLogRingBufEntries * kLogRingBufMsgLen]; #endif } // namespace void SetLogMessageCallback(LogMessageCallback callback) { g_log_callback.store(callback, std::memory_order_relaxed); } void LogMessage(LogLev level, const char* fname, int line, const char* fmt, ...) { char stack_buf[512]; std::unique_ptr large_buf; char* log_msg = &stack_buf[0]; size_t log_msg_len = 0; // By default use a stack allocated buffer because most log messages are quite // short. In rare cases they can be larger (e.g. --help). In those cases we // pay the cost of allocating the buffer on the heap. for (size_t max_len = sizeof(stack_buf);;) { va_list args; va_start(args, fmt); int res = vsnprintf(log_msg, max_len, fmt, args); va_end(args); // If for any reason the print fails, overwrite the message but still print // it. The code below will attach the filename and line, which is still // useful. if (res < 0) { snprintf(log_msg, max_len, "%s", "[printf format error]"); break; } // if res == max_len, vsnprintf saturated the input buffer. Retry with a // larger buffer in that case (within reasonable limits). if (res < static_cast(max_len) || max_len >= 128 * 1024) { // In case of truncation vsnprintf returns the len that "would have been // written if the string was longer", not the actual chars written. log_msg_len = std::min(static_cast(res), max_len - 1); break; } max_len *= 4; large_buf.reset(new char[max_len]); log_msg = &large_buf[0]; } LogMessageCallback cb = g_log_callback.load(std::memory_order_relaxed); if (cb) { cb({level, line, fname, log_msg}); return; } const char* color = kDefault; switch (level) { case kLogDebug: color = kDim; break; case kLogInfo: color = kDefault; break; case kLogImportant: color = kBoldGreen; break; case kLogError: color = kRed; break; } #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) && \ !PERFETTO_BUILDFLAG(PERFETTO_OS_WASM) && \ !PERFETTO_BUILDFLAG(PERFETTO_CHROMIUM_BUILD) static const bool use_colors = isatty(STDERR_FILENO); #else static const bool use_colors = false; #endif // Formats file.cc:line as a space-padded fixed width string. If the file name // |fname| is too long, truncate it on the left-hand side. StackString<10> line_str("%d", line); // 24 will be the width of the file.cc:line column in the log event. static constexpr size_t kMaxNameAndLine = 24; size_t fname_len = strlen(fname); size_t fname_max = kMaxNameAndLine - line_str.len() - 2; // 2 = ':' + '\0'. size_t fname_offset = fname_len <= fname_max ? 0 : fname_len - fname_max; StackString file_and_line( "%*s:%s", static_cast(fname_max), &fname[fname_offset], line_str.c_str()); #if PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID) // Logcat has already timestamping, don't re-emit it. __android_log_print(int{ANDROID_LOG_DEBUG} + level, "perfetto", "%s %s", file_and_line.c_str(), log_msg); #endif // When printing on stderr, print also the timestamp. We don't really care // about the actual time. We just need some reference clock that can be used // to correlated events across differrent processses (e.g. traced and // traced_probes). The wall time % 1000 is good enough. uint32_t t_ms = static_cast(GetWallTimeMs().count()); uint32_t t_sec = t_ms / 1000; t_ms -= t_sec * 1000; t_sec = t_sec % 1000; StackString<32> timestamp("[%03u.%03u] ", t_sec, t_ms); if (use_colors) { fprintf(stderr, "%s%s%s%s %s%s%s\n", kLightGray, timestamp.c_str(), file_and_line.c_str(), kReset, color, log_msg, kReset); } else { fprintf(stderr, "%s%s %s\n", timestamp.c_str(), file_and_line.c_str(), log_msg); } #if PERFETTO_ENABLE_LOG_RING_BUFFER() // Append the message to the ring buffer for crash reporting postmortems. StringView timestamp_sv = timestamp.string_view(); StringView file_and_line_sv = file_and_line.string_view(); StringView log_msg_sv(log_msg, static_cast(log_msg_len)); g_log_ring_buffer.Append(timestamp_sv, file_and_line_sv, log_msg_sv); #else ignore_result(log_msg_len); #endif } #if PERFETTO_ENABLE_LOG_RING_BUFFER() void MaybeSerializeLastLogsForCrashReporting() { // Keep this function minimal. This is called from the watchdog thread, often // when the system is thrashing. // This is racy because two threads could hit a CHECK/FATAL at the same time. // But if that happens we have bigger problems, not worth designing around it. // The behaviour is still defined in the race case (the string attached to // the crash report will contain a mixture of log strings). size_t wr = 0; wr += SerializeCrashKeys(&g_crash_buf[wr], sizeof(g_crash_buf) - wr); wr += g_log_ring_buffer.Read(&g_crash_buf[wr], sizeof(g_crash_buf) - wr); // Read() null-terminates the string properly. This is just to avoid UB when // two threads race on each other (T1 writes a shorter string, T2 // overwrites the \0 writing a longer string. T1 continues here before T2 // finishes writing the longer string with the \0 -> boom. g_crash_buf[sizeof(g_crash_buf) - 1] = '\0'; #if PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID) // android_set_abort_message() will cause debuggerd to report the message // in the tombstone and in the crash log in logcat. // NOTE: android_set_abort_message() can be called only once. This should // be called only when we are sure we are about to crash. android_set_abort_message(g_crash_buf); #else // Print out the message on stderr on Linux/Mac/Win. fputs("\n-----BEGIN PERFETTO PRE-CRASH LOG-----\n", stderr); fputs(g_crash_buf, stderr); fputs("\n-----END PERFETTO PRE-CRASH LOG-----\n", stderr); #endif } #endif // PERFETTO_ENABLE_LOG_RING_BUFFER } // namespace base } // namespace perfetto