1 /*
2 * Copyright (C) 2019 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "perfetto/base/logging.h"
18
19 #include <stdarg.h>
20 #include <stdio.h>
21
22 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
23 #include <unistd.h> // For isatty()
24 #endif
25
26 #include <atomic>
27 #include <memory>
28
29 #include "perfetto/base/build_config.h"
30 #include "perfetto/base/time.h"
31 #include "perfetto/ext/base/crash_keys.h"
32 #include "perfetto/ext/base/string_utils.h"
33 #include "perfetto/ext/base/string_view.h"
34 #include "src/base/log_ring_buffer.h"
35
36 #if PERFETTO_ENABLE_LOG_RING_BUFFER() && PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID)
37 #include <android/set_abort_message.h>
38 #endif
39
40 namespace perfetto {
41 namespace base {
42
43 namespace {
44 const char kReset[] = "\x1b[0m";
45 const char kDefault[] = "\x1b[39m";
46 const char kDim[] = "\x1b[2m";
47 const char kRed[] = "\x1b[31m";
48 const char kBoldGreen[] = "\x1b[1m\x1b[32m";
49 const char kLightGray[] = "\x1b[90m";
50
51 std::atomic<LogMessageCallback> g_log_callback{};
52
53 #if PERFETTO_BUILDFLAG(PERFETTO_STDERR_CRASH_DUMP)
54 // __attribute__((constructor)) causes a static initializer that automagically
55 // early runs this function before the main().
56 void PERFETTO_EXPORT_COMPONENT __attribute__((constructor))
InitDebugCrashReporter()57 InitDebugCrashReporter() {
58 // This function is defined in debug_crash_stack_trace.cc.
59 // The dynamic initializer is in logging.cc because logging.cc is included
60 // in virtually any target that depends on base. Having it in
61 // debug_crash_stack_trace.cc would require figuring out -Wl,whole-archive
62 // which is not worth it.
63 EnableStacktraceOnCrashForDebug();
64 }
65 #endif
66
67 #if PERFETTO_ENABLE_LOG_RING_BUFFER()
68 LogRingBuffer g_log_ring_buffer{};
69
70 // This is global to avoid allocating memory or growing too much the stack
71 // in MaybeSerializeLastLogsForCrashReporting(), which is called from
72 // arbitrary code paths hitting PERFETTO_CHECK()/FATAL().
73 char g_crash_buf[kLogRingBufEntries * kLogRingBufMsgLen];
74 #endif
75
76 } // namespace
77
SetLogMessageCallback(LogMessageCallback callback)78 void SetLogMessageCallback(LogMessageCallback callback) {
79 g_log_callback.store(callback, std::memory_order_relaxed);
80 }
81
LogMessage(LogLev level,const char * fname,int line,const char * fmt,...)82 void LogMessage(LogLev level,
83 const char* fname,
84 int line,
85 const char* fmt,
86 ...) {
87 char stack_buf[512];
88 std::unique_ptr<char[]> large_buf;
89 char* log_msg = &stack_buf[0];
90 size_t log_msg_len = 0;
91
92 // By default use a stack allocated buffer because most log messages are quite
93 // short. In rare cases they can be larger (e.g. --help). In those cases we
94 // pay the cost of allocating the buffer on the heap.
95 for (size_t max_len = sizeof(stack_buf);;) {
96 va_list args;
97 va_start(args, fmt);
98 int res = vsnprintf(log_msg, max_len, fmt, args);
99 va_end(args);
100
101 // If for any reason the print fails, overwrite the message but still print
102 // it. The code below will attach the filename and line, which is still
103 // useful.
104 if (res < 0) {
105 snprintf(log_msg, max_len, "%s", "[printf format error]");
106 break;
107 }
108
109 // if res == max_len, vsnprintf saturated the input buffer. Retry with a
110 // larger buffer in that case (within reasonable limits).
111 if (res < static_cast<int>(max_len) || max_len >= 128 * 1024) {
112 // In case of truncation vsnprintf returns the len that "would have been
113 // written if the string was longer", not the actual chars written.
114 log_msg_len = std::min(static_cast<size_t>(res), max_len - 1);
115 break;
116 }
117 max_len *= 4;
118 large_buf.reset(new char[max_len]);
119 log_msg = &large_buf[0];
120 }
121
122 LogMessageCallback cb = g_log_callback.load(std::memory_order_relaxed);
123 if (cb) {
124 cb({level, line, fname, log_msg});
125 return;
126 }
127
128 const char* color = kDefault;
129 switch (level) {
130 case kLogDebug:
131 color = kDim;
132 break;
133 case kLogInfo:
134 color = kDefault;
135 break;
136 case kLogImportant:
137 color = kBoldGreen;
138 break;
139 case kLogError:
140 color = kRed;
141 break;
142 }
143
144 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) && \
145 !PERFETTO_BUILDFLAG(PERFETTO_OS_WASM) && \
146 !PERFETTO_BUILDFLAG(PERFETTO_CHROMIUM_BUILD)
147 static const bool use_colors = isatty(STDERR_FILENO);
148 #else
149 static const bool use_colors = false;
150 #endif
151
152 // Formats file.cc:line as a space-padded fixed width string. If the file name
153 // |fname| is too long, truncate it on the left-hand side.
154 StackString<10> line_str("%d", line);
155
156 // 24 will be the width of the file.cc:line column in the log event.
157 static constexpr size_t kMaxNameAndLine = 24;
158 size_t fname_len = strlen(fname);
159 size_t fname_max = kMaxNameAndLine - line_str.len() - 2; // 2 = ':' + '\0'.
160 size_t fname_offset = fname_len <= fname_max ? 0 : fname_len - fname_max;
161 StackString<kMaxNameAndLine> file_and_line(
162 "%*s:%s", static_cast<int>(fname_max), &fname[fname_offset],
163 line_str.c_str());
164
165 #if PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID)
166 // Logcat has already timestamping, don't re-emit it.
167 __android_log_print(int{ANDROID_LOG_DEBUG} + level, "perfetto", "%s %s",
168 file_and_line.c_str(), log_msg);
169 #endif
170
171 // When printing on stderr, print also the timestamp. We don't really care
172 // about the actual time. We just need some reference clock that can be used
173 // to correlated events across differrent processses (e.g. traced and
174 // traced_probes). The wall time % 1000 is good enough.
175 uint32_t t_ms = static_cast<uint32_t>(GetWallTimeMs().count());
176 uint32_t t_sec = t_ms / 1000;
177 t_ms -= t_sec * 1000;
178 t_sec = t_sec % 1000;
179 StackString<32> timestamp("[%03u.%03u] ", t_sec, t_ms);
180
181 if (use_colors) {
182 fprintf(stderr, "%s%s%s%s %s%s%s\n", kLightGray, timestamp.c_str(),
183 file_and_line.c_str(), kReset, color, log_msg, kReset);
184 } else {
185 fprintf(stderr, "%s%s %s\n", timestamp.c_str(), file_and_line.c_str(),
186 log_msg);
187 }
188
189 #if PERFETTO_ENABLE_LOG_RING_BUFFER()
190 // Append the message to the ring buffer for crash reporting postmortems.
191 StringView timestamp_sv = timestamp.string_view();
192 StringView file_and_line_sv = file_and_line.string_view();
193 StringView log_msg_sv(log_msg, static_cast<size_t>(log_msg_len));
194 g_log_ring_buffer.Append(timestamp_sv, file_and_line_sv, log_msg_sv);
195 #else
196 ignore_result(log_msg_len);
197 #endif
198 }
199
200 #if PERFETTO_ENABLE_LOG_RING_BUFFER()
MaybeSerializeLastLogsForCrashReporting()201 void MaybeSerializeLastLogsForCrashReporting() {
202 // Keep this function minimal. This is called from the watchdog thread, often
203 // when the system is thrashing.
204
205 // This is racy because two threads could hit a CHECK/FATAL at the same time.
206 // But if that happens we have bigger problems, not worth designing around it.
207 // The behaviour is still defined in the race case (the string attached to
208 // the crash report will contain a mixture of log strings).
209 size_t wr = 0;
210 wr += SerializeCrashKeys(&g_crash_buf[wr], sizeof(g_crash_buf) - wr);
211 wr += g_log_ring_buffer.Read(&g_crash_buf[wr], sizeof(g_crash_buf) - wr);
212
213 // Read() null-terminates the string properly. This is just to avoid UB when
214 // two threads race on each other (T1 writes a shorter string, T2
215 // overwrites the \0 writing a longer string. T1 continues here before T2
216 // finishes writing the longer string with the \0 -> boom.
217 g_crash_buf[sizeof(g_crash_buf) - 1] = '\0';
218
219 #if PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID)
220 // android_set_abort_message() will cause debuggerd to report the message
221 // in the tombstone and in the crash log in logcat.
222 // NOTE: android_set_abort_message() can be called only once. This should
223 // be called only when we are sure we are about to crash.
224 android_set_abort_message(g_crash_buf);
225 #else
226 // Print out the message on stderr on Linux/Mac/Win.
227 fputs("\n-----BEGIN PERFETTO PRE-CRASH LOG-----\n", stderr);
228 fputs(g_crash_buf, stderr);
229 fputs("\n-----END PERFETTO PRE-CRASH LOG-----\n", stderr);
230 #endif
231 }
232 #endif // PERFETTO_ENABLE_LOG_RING_BUFFER
233
234 } // namespace base
235 } // namespace perfetto
236