1 /*
2 * Copyright (C) 2015 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 #if defined(_WIN32)
18 #include <windows.h>
19 #endif
20
21 #include "android-base/logging.h"
22
23 #include <fcntl.h>
24 #include <inttypes.h>
25 #include <libgen.h>
26 #include <time.h>
27
28 // For getprogname(3) or program_invocation_short_name.
29 #if defined(__ANDROID__) || defined(__APPLE__)
30 #include <stdlib.h>
31 #elif defined(__GLIBC__)
32 #include <errno.h>
33 #endif
34
35 #include <atomic>
36 #include <iostream>
37 #include <limits>
38 #include <mutex>
39 #include <optional>
40 #include <sstream>
41 #include <string>
42 #include <utility>
43 #include <vector>
44
45 #include <android/log.h>
46 #ifdef __ANDROID__
47 #include <android/set_abort_message.h>
48 #else
49 #include <sys/types.h>
50 #include <unistd.h>
51 #endif
52
53 #include <android-base/file.h>
54 #include <android-base/macros.h>
55 #include <android-base/parseint.h>
56 #include <android-base/strings.h>
57 #include <android-base/threads.h>
58
59 #include "logging_splitters.h"
60
61 namespace android {
62 namespace base {
63
64 // BSD-based systems like Android/macOS have getprogname(). Others need us to provide one.
65 #if !defined(__APPLE__) && !defined(__BIONIC__)
getprogname()66 static const char* getprogname() {
67 #ifdef _WIN32
68 static bool first = true;
69 static char progname[MAX_PATH] = {};
70
71 if (first) {
72 snprintf(progname, sizeof(progname), "%s",
73 android::base::Basename(android::base::GetExecutablePath()).c_str());
74 first = false;
75 }
76
77 return progname;
78 #else
79 return program_invocation_short_name;
80 #endif
81 }
82 #endif
83
GetFileBasename(const char * file)84 static const char* GetFileBasename(const char* file) {
85 // We can't use basename(3) even on Unix because the Mac doesn't
86 // have a non-modifying basename.
87 const char* last_slash = strrchr(file, '/');
88 if (last_slash != nullptr) {
89 return last_slash + 1;
90 }
91 #if defined(_WIN32)
92 const char* last_backslash = strrchr(file, '\\');
93 if (last_backslash != nullptr) {
94 return last_backslash + 1;
95 }
96 #endif
97 return file;
98 }
99
100 #if defined(__linux__)
OpenKmsg()101 static int OpenKmsg() {
102 #if defined(__ANDROID__)
103 // Pick up `file /dev/kmsg w` environment from a daemon's init .rc file.
104 // If you're wondering why you're not seeing kernel logs from your daemon,
105 // it's probably because you're missing that line in your .rc file!
106 // You'll also need to `allow <your_domain> kmsg_device:chr_file w_file_perms;`
107 // in `system/sepolocy/private/<your_domain>.te`.
108 const auto val = getenv("ANDROID_FILE__dev_kmsg");
109 if (val != nullptr) {
110 int fd;
111 if (android::base::ParseInt(val, &fd, 0)) {
112 auto flags = fcntl(fd, F_GETFL);
113 if ((flags != -1) && ((flags & O_ACCMODE) == O_WRONLY)) return fd;
114 }
115 }
116 #endif
117 // Note that this is _not_ the normal case: this is primarily for init itself.
118 // Most other code will need to inherit an fd from init, as described above.
119 return TEMP_FAILURE_RETRY(open("/dev/kmsg", O_WRONLY | O_CLOEXEC));
120 }
121 #endif
122
log_id_tToLogId(int32_t buffer_id)123 static LogId log_id_tToLogId(int32_t buffer_id) {
124 switch (buffer_id) {
125 case LOG_ID_MAIN:
126 return MAIN;
127 case LOG_ID_SYSTEM:
128 return SYSTEM;
129 case LOG_ID_RADIO:
130 return RADIO;
131 case LOG_ID_CRASH:
132 return CRASH;
133 case LOG_ID_DEFAULT:
134 default:
135 return DEFAULT;
136 }
137 }
138
LogIdTolog_id_t(LogId log_id)139 static int32_t LogIdTolog_id_t(LogId log_id) {
140 switch (log_id) {
141 case MAIN:
142 return LOG_ID_MAIN;
143 case SYSTEM:
144 return LOG_ID_SYSTEM;
145 case RADIO:
146 return LOG_ID_RADIO;
147 case CRASH:
148 return LOG_ID_CRASH;
149 case DEFAULT:
150 default:
151 return LOG_ID_DEFAULT;
152 }
153 }
154
PriorityToLogSeverity(int priority)155 static LogSeverity PriorityToLogSeverity(int priority) {
156 switch (priority) {
157 case ANDROID_LOG_DEFAULT:
158 return INFO;
159 case ANDROID_LOG_VERBOSE:
160 return VERBOSE;
161 case ANDROID_LOG_DEBUG:
162 return DEBUG;
163 case ANDROID_LOG_INFO:
164 return INFO;
165 case ANDROID_LOG_WARN:
166 return WARNING;
167 case ANDROID_LOG_ERROR:
168 return ERROR;
169 case ANDROID_LOG_FATAL:
170 return FATAL;
171 default:
172 return FATAL;
173 }
174 }
175
LogSeverityToPriority(LogSeverity severity)176 static int32_t LogSeverityToPriority(LogSeverity severity) {
177 switch (severity) {
178 case VERBOSE:
179 return ANDROID_LOG_VERBOSE;
180 case DEBUG:
181 return ANDROID_LOG_DEBUG;
182 case INFO:
183 return ANDROID_LOG_INFO;
184 case WARNING:
185 return ANDROID_LOG_WARN;
186 case ERROR:
187 return ANDROID_LOG_ERROR;
188 case FATAL_WITHOUT_ABORT:
189 case FATAL:
190 default:
191 return ANDROID_LOG_FATAL;
192 }
193 }
194
Logger()195 static LogFunction& Logger() {
196 #ifdef __ANDROID__
197 static auto& logger = *new LogFunction(LogdLogger());
198 #else
199 static auto& logger = *new LogFunction(StderrLogger);
200 #endif
201 return logger;
202 }
203
Aborter()204 static AbortFunction& Aborter() {
205 static auto& aborter = *new AbortFunction(DefaultAborter);
206 return aborter;
207 }
208
209 // Only used for Q fallback.
TagLock()210 static std::recursive_mutex& TagLock() {
211 static auto& tag_lock = *new std::recursive_mutex();
212 return tag_lock;
213 }
214 // Only used for Q fallback.
215 static std::string* gDefaultTag;
216
SetDefaultTag(const std::string & tag)217 void SetDefaultTag(const std::string& tag) {
218 if (__builtin_available(android 30, *)) {
219 __android_log_set_default_tag(tag.c_str());
220 } else {
221 std::lock_guard<std::recursive_mutex> lock(TagLock());
222 if (gDefaultTag != nullptr) {
223 delete gDefaultTag;
224 gDefaultTag = nullptr;
225 }
226 if (!tag.empty()) {
227 gDefaultTag = new std::string(tag);
228 }
229 }
230 }
231
232 static bool gInitialized = false;
233
234 // Only used for Q fallback.
235 static LogSeverity gMinimumLogSeverity = INFO;
236
237 #if defined(__linux__)
KernelLogLine(const char * msg,int length,android::base::LogSeverity severity,const char * tag)238 static void KernelLogLine(const char* msg, int length, android::base::LogSeverity severity,
239 const char* tag) {
240 // clang-format off
241 static constexpr int kLogSeverityToKernelLogLevel[] = {
242 [android::base::VERBOSE] = 7, // KERN_DEBUG (there is no verbose kernel log
243 // level)
244 [android::base::DEBUG] = 7, // KERN_DEBUG
245 [android::base::INFO] = 6, // KERN_INFO
246 [android::base::WARNING] = 4, // KERN_WARNING
247 [android::base::ERROR] = 3, // KERN_ERROR
248 [android::base::FATAL_WITHOUT_ABORT] = 2, // KERN_CRIT
249 [android::base::FATAL] = 2, // KERN_CRIT
250 };
251 // clang-format on
252 static_assert(arraysize(kLogSeverityToKernelLogLevel) == android::base::FATAL + 1,
253 "Mismatch in size of kLogSeverityToKernelLogLevel and values in LogSeverity");
254
255 static int klog_fd = OpenKmsg();
256 if (klog_fd == -1) return;
257
258 int level = kLogSeverityToKernelLogLevel[severity];
259
260 // The kernel's printk buffer is only |1024 - PREFIX_MAX| bytes, where
261 // PREFIX_MAX could be 48 or 32.
262 // Reference: kernel/printk/printk.c
263 static constexpr int LOG_LINE_MAX = 1024 - 48;
264 char buf[LOG_LINE_MAX] __attribute__((__uninitialized__));
265 size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %.*s\n", level, tag, length, msg);
266 TEMP_FAILURE_RETRY(write(klog_fd, buf, std::min(size, sizeof(buf))));
267
268 if (size > sizeof(buf)) {
269 size_t truncated = size - sizeof(buf);
270 size = snprintf(
271 buf, sizeof(buf),
272 "<%d>%s: **previous message missing %zu bytes** %zu-byte message too long for printk\n",
273 level, tag, truncated, size);
274 TEMP_FAILURE_RETRY(write(klog_fd, buf, std::min(size, sizeof(buf))));
275 }
276 }
277
KernelLogger(android::base::LogId,android::base::LogSeverity severity,const char * tag,const char *,unsigned int,const char * full_message)278 void KernelLogger(android::base::LogId, android::base::LogSeverity severity, const char* tag,
279 const char*, unsigned int, const char* full_message) {
280 SplitByLines(full_message, KernelLogLine, severity, tag);
281 }
282 #endif
283
StderrLogger(LogId,LogSeverity severity,const char * tag,const char * file,unsigned int line,const char * message)284 void StderrLogger(LogId, LogSeverity severity, const char* tag, const char* file, unsigned int line,
285 const char* message) {
286 struct timespec ts;
287 clock_gettime(CLOCK_REALTIME, &ts);
288 auto output_string =
289 StderrOutputGenerator(ts, getpid(), GetThreadId(), severity, tag, file, line, message);
290
291 fputs(output_string.c_str(), stderr);
292 }
293
StdioLogger(LogId,LogSeverity severity,const char *,const char *,unsigned int,const char * message)294 void StdioLogger(LogId, LogSeverity severity, const char* /*tag*/, const char* /*file*/,
295 unsigned int /*line*/, const char* message) {
296 if (severity >= WARNING) {
297 fflush(stdout);
298 fprintf(stderr, "%s: %s\n", GetFileBasename(getprogname()), message);
299 } else {
300 fprintf(stdout, "%s\n", message);
301 }
302 }
303
TeeLogger(LogFunction && l1,LogFunction && l2)304 LogFunction TeeLogger(LogFunction&& l1, LogFunction&& l2) {
305 return [l1 = std::move(l1), l2 = std::move(l2)](LogId id, LogSeverity severity, const char* tag,
306 const char* file, unsigned int line,
307 const char* message) {
308 l1(id, severity, tag, file, line, message);
309 l2(id, severity, tag, file, line, message);
310 };
311 }
312
DefaultAborter(const char * abort_message)313 void DefaultAborter(const char* abort_message) {
314 #ifdef __ANDROID__
315 android_set_abort_message(abort_message);
316 #else
317 UNUSED(abort_message);
318 #endif
319 abort();
320 }
321
LogdLogChunk(LogId id,LogSeverity severity,const char * tag,const char * message)322 static void LogdLogChunk(LogId id, LogSeverity severity, const char* tag, const char* message) {
323 int32_t lg_id = LogIdTolog_id_t(id);
324 int32_t priority = LogSeverityToPriority(severity);
325
326 if (__builtin_available(android 30, *)) {
327 __android_log_message log_message = {sizeof(__android_log_message), lg_id, priority, tag,
328 static_cast<const char*>(nullptr), 0, message};
329 __android_log_logd_logger(&log_message);
330 } else {
331 __android_log_buf_print(lg_id, priority, tag, "%s", message);
332 }
333 }
334
LogdLogger(LogId default_log_id)335 LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) {}
336
operator ()(LogId id,LogSeverity severity,const char * tag,const char * file,unsigned int line,const char * message)337 void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag, const char* file,
338 unsigned int line, const char* message) {
339 if (id == DEFAULT) {
340 id = default_log_id_;
341 }
342
343 SplitByLogdChunks(id, severity, tag, file, line, message, LogdLogChunk);
344 }
345
InitLogging(char * argv[],LogFunction && logger,AbortFunction && aborter)346 void InitLogging(char* argv[], LogFunction&& logger, AbortFunction&& aborter) {
347 SetLogger(std::forward<LogFunction>(logger));
348 SetAborter(std::forward<AbortFunction>(aborter));
349
350 if (gInitialized) {
351 return;
352 }
353
354 gInitialized = true;
355
356 // Stash the command line for later use. We can use /proc/self/cmdline on
357 // Linux to recover this, but we don't have that luxury on the Mac/Windows,
358 // and there are a couple of argv[0] variants that are commonly used.
359 if (argv != nullptr) {
360 SetDefaultTag(basename(argv[0]));
361 }
362
363 const char* tags = getenv("ANDROID_LOG_TAGS");
364 if (tags == nullptr) {
365 return;
366 }
367
368 std::vector<std::string> specs = Split(tags, " ");
369 for (size_t i = 0; i < specs.size(); ++i) {
370 // "tag-pattern:[vdiwefs]"
371 std::string spec(specs[i]);
372 if (spec.size() == 3 && StartsWith(spec, "*:")) {
373 switch (spec[2]) {
374 case 'v':
375 SetMinimumLogSeverity(VERBOSE);
376 continue;
377 case 'd':
378 SetMinimumLogSeverity(DEBUG);
379 continue;
380 case 'i':
381 SetMinimumLogSeverity(INFO);
382 continue;
383 case 'w':
384 SetMinimumLogSeverity(WARNING);
385 continue;
386 case 'e':
387 SetMinimumLogSeverity(ERROR);
388 continue;
389 case 'f':
390 SetMinimumLogSeverity(FATAL_WITHOUT_ABORT);
391 continue;
392 // liblog will even suppress FATAL if you say 's' for silent, but fatal should
393 // never be suppressed.
394 case 's':
395 SetMinimumLogSeverity(FATAL_WITHOUT_ABORT);
396 continue;
397 }
398 }
399 LOG(FATAL) << "unsupported '" << spec << "' in ANDROID_LOG_TAGS (" << tags
400 << ")";
401 }
402 }
403
SetLogger(LogFunction && logger)404 LogFunction SetLogger(LogFunction&& logger) {
405 LogFunction old_logger = std::move(Logger());
406 Logger() = std::move(logger);
407
408 if (__builtin_available(android 30, *)) {
409 __android_log_set_logger([](const struct __android_log_message* log_message) {
410 auto log_id = log_id_tToLogId(log_message->buffer_id);
411 auto severity = PriorityToLogSeverity(log_message->priority);
412
413 Logger()(log_id, severity, log_message->tag, log_message->file, log_message->line,
414 log_message->message);
415 });
416 }
417 return old_logger;
418 }
419
SetAborter(AbortFunction && aborter)420 AbortFunction SetAborter(AbortFunction&& aborter) {
421 AbortFunction old_aborter = std::move(Aborter());
422 Aborter() = std::move(aborter);
423
424 if (__builtin_available(android 30, *)) {
425 __android_log_set_aborter([](const char* abort_message) { Aborter()(abort_message); });
426 }
427 return old_aborter;
428 }
429
430 // This indirection greatly reduces the stack impact of having lots of
431 // checks/logging in a function.
432 class LogMessageData {
433 public:
LogMessageData(const char * file,unsigned int line,LogSeverity severity,const char * tag,int error)434 LogMessageData(const char* file, unsigned int line, LogSeverity severity, const char* tag,
435 int error)
436 : file_(GetFileBasename(file)),
437 line_number_(line),
438 severity_(severity),
439 tag_(tag),
440 error_(error) {}
441
GetFile() const442 const char* GetFile() const {
443 return file_;
444 }
445
GetLineNumber() const446 unsigned int GetLineNumber() const {
447 return line_number_;
448 }
449
GetSeverity() const450 LogSeverity GetSeverity() const {
451 return severity_;
452 }
453
GetTag() const454 const char* GetTag() const { return tag_; }
455
GetError() const456 int GetError() const {
457 return error_;
458 }
459
GetBuffer()460 std::ostream& GetBuffer() {
461 return buffer_;
462 }
463
ToString() const464 std::string ToString() const {
465 return buffer_.str();
466 }
467
468 private:
469 std::ostringstream buffer_;
470 const char* const file_;
471 const unsigned int line_number_;
472 const LogSeverity severity_;
473 const char* const tag_;
474 const int error_;
475
476 DISALLOW_COPY_AND_ASSIGN(LogMessageData);
477 };
478
LogMessage(const char * file,unsigned int line,LogId,LogSeverity severity,const char * tag,int error)479 LogMessage::LogMessage(const char* file, unsigned int line, LogId, LogSeverity severity,
480 const char* tag, int error)
481 : LogMessage(file, line, severity, tag, error) {}
482
LogMessage(const char * file,unsigned int line,LogSeverity severity,const char * tag,int error)483 LogMessage::LogMessage(const char* file, unsigned int line, LogSeverity severity, const char* tag,
484 int error)
485 : data_(new LogMessageData(file, line, severity, tag, error)) {}
486
~LogMessage()487 LogMessage::~LogMessage() {
488 // Check severity again. This is duplicate work wrt/ LOG macros, but not LOG_STREAM.
489 if (!WOULD_LOG(data_->GetSeverity())) {
490 return;
491 }
492
493 // Finish constructing the message.
494 if (data_->GetError() != -1) {
495 data_->GetBuffer() << ": " << strerror(data_->GetError());
496 }
497 std::string msg(data_->ToString());
498
499 if (data_->GetSeverity() == FATAL) {
500 #ifdef __ANDROID__
501 // Set the bionic abort message early to avoid liblog doing it
502 // with the individual lines, so that we get the whole message.
503 android_set_abort_message(msg.c_str());
504 #endif
505 }
506
507 LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), data_->GetTag(),
508 msg.c_str());
509
510 // Abort if necessary.
511 if (data_->GetSeverity() == FATAL) {
512 if (__builtin_available(android 30, *)) {
513 __android_log_call_aborter(msg.c_str());
514 } else {
515 Aborter()(msg.c_str());
516 }
517 }
518 }
519
stream()520 std::ostream& LogMessage::stream() {
521 return data_->GetBuffer();
522 }
523
LogLine(const char * file,unsigned int line,LogSeverity severity,const char * tag,const char * message)524 void LogMessage::LogLine(const char* file, unsigned int line, LogSeverity severity, const char* tag,
525 const char* message) {
526 int32_t priority = LogSeverityToPriority(severity);
527 if (__builtin_available(android 30, *)) {
528 __android_log_message log_message = {
529 sizeof(__android_log_message), LOG_ID_DEFAULT, priority, tag, file, line, message};
530 __android_log_write_log_message(&log_message);
531 } else {
532 if (tag == nullptr) {
533 std::lock_guard<std::recursive_mutex> lock(TagLock());
534 if (gDefaultTag == nullptr) {
535 gDefaultTag = new std::string(getprogname());
536 }
537
538 Logger()(DEFAULT, severity, gDefaultTag->c_str(), file, line, message);
539 } else {
540 Logger()(DEFAULT, severity, tag, file, line, message);
541 }
542 }
543 }
544
GetMinimumLogSeverity()545 LogSeverity GetMinimumLogSeverity() {
546 if (__builtin_available(android 30, *)) {
547 return PriorityToLogSeverity(__android_log_get_minimum_priority());
548 } else {
549 return gMinimumLogSeverity;
550 }
551 }
552
ShouldLog(LogSeverity severity,const char * tag)553 bool ShouldLog(LogSeverity severity, const char* tag) {
554 // Even though we're not using the R liblog functions in this function, if we're running on Q,
555 // we need to fall back to using gMinimumLogSeverity, since __android_log_is_loggable() will not
556 // take into consideration the value from SetMinimumLogSeverity().
557 if (__builtin_available(android 30, *)) {
558 int32_t priority = LogSeverityToPriority(severity);
559 return __android_log_is_loggable(priority, tag, ANDROID_LOG_INFO);
560 } else {
561 return severity >= gMinimumLogSeverity;
562 }
563 }
564
SetMinimumLogSeverity(LogSeverity new_severity)565 LogSeverity SetMinimumLogSeverity(LogSeverity new_severity) {
566 if (__builtin_available(android 30, *)) {
567 int32_t priority = LogSeverityToPriority(new_severity);
568 return PriorityToLogSeverity(__android_log_set_minimum_priority(priority));
569 } else {
570 LogSeverity old_severity = gMinimumLogSeverity;
571 gMinimumLogSeverity = new_severity;
572 return old_severity;
573 }
574 }
575
ScopedLogSeverity(LogSeverity new_severity)576 ScopedLogSeverity::ScopedLogSeverity(LogSeverity new_severity) {
577 old_ = SetMinimumLogSeverity(new_severity);
578 }
579
~ScopedLogSeverity()580 ScopedLogSeverity::~ScopedLogSeverity() {
581 SetMinimumLogSeverity(old_);
582 }
583
584 } // namespace base
585 } // namespace android
586