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