Home | History | Annotate | Download | only in base 
      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 <libgen.h>
     25 #include <time.h>
     26 
     27 // For getprogname(3) or program_invocation_short_name.
     28 #if defined(__ANDROID__) || defined(__APPLE__)
     29 #include <stdlib.h>
     30 #elif defined(__GLIBC__)
     31 #include <errno.h>
     32 #endif
     33 
     34 #if defined(__linux__)
     35 #include <sys/uio.h>
     36 #endif
     37 
     38 #include <iostream>
     39 #include <limits>
     40 #include <mutex>
     41 #include <sstream>
     42 #include <string>
     43 #include <utility>
     44 #include <vector>
     45 
     46 // Headers for LogMessage::LogLine.
     47 #ifdef __ANDROID__
     48 #include <log/log.h>
     49 #include <android/set_abort_message.h>
     50 #else
     51 #include <sys/types.h>
     52 #include <unistd.h>
     53 #endif
     54 
     55 #include <android-base/macros.h>
     56 #include <android-base/strings.h>
     57 
     58 // For gettid.
     59 #if defined(__APPLE__)
     60 #include "AvailabilityMacros.h"  // For MAC_OS_X_VERSION_MAX_ALLOWED
     61 #include <stdint.h>
     62 #include <stdlib.h>
     63 #include <sys/syscall.h>
     64 #include <sys/time.h>
     65 #include <unistd.h>
     66 #elif defined(__linux__) && !defined(__ANDROID__)
     67 #include <syscall.h>
     68 #include <unistd.h>
     69 #elif defined(_WIN32)
     70 #include <windows.h>
     71 #endif
     72 
     73 #if defined(_WIN32)
     74 typedef uint32_t thread_id;
     75 #else
     76 typedef pid_t thread_id;
     77 #endif
     78 
     79 static thread_id GetThreadId() {
     80 #if defined(__BIONIC__)
     81   return gettid();
     82 #elif defined(__APPLE__)
     83   return syscall(SYS_thread_selfid);
     84 #elif defined(__linux__)
     85   return syscall(__NR_gettid);
     86 #elif defined(_WIN32)
     87   return GetCurrentThreadId();
     88 #endif
     89 }
     90 
     91 namespace {
     92 #if defined(__GLIBC__)
     93 const char* getprogname() {
     94   return program_invocation_short_name;
     95 }
     96 #elif defined(_WIN32)
     97 const char* getprogname() {
     98   static bool first = true;
     99   static char progname[MAX_PATH] = {};
    100 
    101   if (first) {
    102     CHAR longname[MAX_PATH];
    103     DWORD nchars = GetModuleFileNameA(nullptr, longname, arraysize(longname));
    104     if ((nchars >= arraysize(longname)) || (nchars == 0)) {
    105       // String truncation or some other error.
    106       strcpy(progname, "<unknown>");
    107     } else {
    108       strcpy(progname, basename(longname));
    109     }
    110     first = false;
    111   }
    112 
    113   return progname;
    114 }
    115 #endif
    116 } // namespace
    117 
    118 namespace android {
    119 namespace base {
    120 
    121 static std::mutex& LoggingLock() {
    122   static auto& logging_lock = *new std::mutex();
    123   return logging_lock;
    124 }
    125 
    126 static LogFunction& Logger() {
    127 #ifdef __ANDROID__
    128   static auto& logger = *new LogFunction(LogdLogger());
    129 #else
    130   static auto& logger = *new LogFunction(StderrLogger);
    131 #endif
    132   return logger;
    133 }
    134 
    135 static AbortFunction& Aborter() {
    136   static auto& aborter = *new AbortFunction(DefaultAborter);
    137   return aborter;
    138 }
    139 
    140 static std::string& ProgramInvocationName() {
    141   static auto& programInvocationName = *new std::string(getprogname());
    142   return programInvocationName;
    143 }
    144 
    145 static bool gInitialized = false;
    146 static LogSeverity gMinimumLogSeverity = INFO;
    147 
    148 #if defined(__linux__)
    149 void KernelLogger(android::base::LogId, android::base::LogSeverity severity,
    150                   const char* tag, const char*, unsigned int, const char* msg) {
    151   // clang-format off
    152   static constexpr int kLogSeverityToKernelLogLevel[] = {
    153       [android::base::VERBOSE] = 7,              // KERN_DEBUG (there is no verbose kernel log
    154                                                  //             level)
    155       [android::base::DEBUG] = 7,                // KERN_DEBUG
    156       [android::base::INFO] = 6,                 // KERN_INFO
    157       [android::base::WARNING] = 4,              // KERN_WARNING
    158       [android::base::ERROR] = 3,                // KERN_ERROR
    159       [android::base::FATAL_WITHOUT_ABORT] = 2,  // KERN_CRIT
    160       [android::base::FATAL] = 2,                // KERN_CRIT
    161   };
    162   // clang-format on
    163   static_assert(arraysize(kLogSeverityToKernelLogLevel) == android::base::FATAL + 1,
    164                 "Mismatch in size of kLogSeverityToKernelLogLevel and values in LogSeverity");
    165 
    166   static int klog_fd = TEMP_FAILURE_RETRY(open("/dev/kmsg", O_WRONLY | O_CLOEXEC));
    167   if (klog_fd == -1) return;
    168 
    169   int level = kLogSeverityToKernelLogLevel[severity];
    170 
    171   // The kernel's printk buffer is only 1024 bytes.
    172   // TODO: should we automatically break up long lines into multiple lines?
    173   // Or we could log but with something like "..." at the end?
    174   char buf[1024];
    175   size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %s\n", level, tag, msg);
    176   if (size > sizeof(buf)) {
    177     size = snprintf(buf, sizeof(buf), "<%d>%s: %zu-byte message too long for printk\n",
    178                     level, tag, size);
    179   }
    180 
    181   iovec iov[1];
    182   iov[0].iov_base = buf;
    183   iov[0].iov_len = size;
    184   TEMP_FAILURE_RETRY(writev(klog_fd, iov, 1));
    185 }
    186 #endif
    187 
    188 void StderrLogger(LogId, LogSeverity severity, const char*, const char* file,
    189                   unsigned int line, const char* message) {
    190   struct tm now;
    191   time_t t = time(nullptr);
    192 
    193 #if defined(_WIN32)
    194   localtime_s(&now, &t);
    195 #else
    196   localtime_r(&t, &now);
    197 #endif
    198 
    199   char timestamp[32];
    200   strftime(timestamp, sizeof(timestamp), "%m-%d %H:%M:%S", &now);
    201 
    202   static const char log_characters[] = "VDIWEFF";
    203   static_assert(arraysize(log_characters) - 1 == FATAL + 1,
    204                 "Mismatch in size of log_characters and values in LogSeverity");
    205   char severity_char = log_characters[severity];
    206   fprintf(stderr, "%s %c %s %5d %5d %s:%u] %s\n", ProgramInvocationName().c_str(),
    207           severity_char, timestamp, getpid(), GetThreadId(), file, line, message);
    208 }
    209 
    210 void DefaultAborter(const char* abort_message) {
    211 #ifdef __ANDROID__
    212   android_set_abort_message(abort_message);
    213 #else
    214   UNUSED(abort_message);
    215 #endif
    216   abort();
    217 }
    218 
    219 
    220 #ifdef __ANDROID__
    221 LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) {
    222 }
    223 
    224 void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag,
    225                             const char* file, unsigned int line,
    226                             const char* message) {
    227   static constexpr android_LogPriority kLogSeverityToAndroidLogPriority[] = {
    228       ANDROID_LOG_VERBOSE, ANDROID_LOG_DEBUG, ANDROID_LOG_INFO,
    229       ANDROID_LOG_WARN,    ANDROID_LOG_ERROR, ANDROID_LOG_FATAL,
    230       ANDROID_LOG_FATAL,
    231   };
    232   static_assert(arraysize(kLogSeverityToAndroidLogPriority) == FATAL + 1,
    233                 "Mismatch in size of kLogSeverityToAndroidLogPriority and values in LogSeverity");
    234 
    235   int priority = kLogSeverityToAndroidLogPriority[severity];
    236   if (id == DEFAULT) {
    237     id = default_log_id_;
    238   }
    239 
    240   static constexpr log_id kLogIdToAndroidLogId[] = {
    241     LOG_ID_MAX, LOG_ID_MAIN, LOG_ID_SYSTEM,
    242   };
    243   static_assert(arraysize(kLogIdToAndroidLogId) == SYSTEM + 1,
    244                 "Mismatch in size of kLogIdToAndroidLogId and values in LogId");
    245   log_id lg_id = kLogIdToAndroidLogId[id];
    246 
    247   if (priority == ANDROID_LOG_FATAL) {
    248     __android_log_buf_print(lg_id, priority, tag, "%s:%u] %s", file, line,
    249                             message);
    250   } else {
    251     __android_log_buf_print(lg_id, priority, tag, "%s", message);
    252   }
    253 }
    254 #endif
    255 
    256 void InitLogging(char* argv[], LogFunction&& logger, AbortFunction&& aborter) {
    257   SetLogger(std::forward<LogFunction>(logger));
    258   SetAborter(std::forward<AbortFunction>(aborter));
    259 
    260   if (gInitialized) {
    261     return;
    262   }
    263 
    264   gInitialized = true;
    265 
    266   // Stash the command line for later use. We can use /proc/self/cmdline on
    267   // Linux to recover this, but we don't have that luxury on the Mac/Windows,
    268   // and there are a couple of argv[0] variants that are commonly used.
    269   if (argv != nullptr) {
    270     std::lock_guard<std::mutex> lock(LoggingLock());
    271     ProgramInvocationName() = basename(argv[0]);
    272   }
    273 
    274   const char* tags = getenv("ANDROID_LOG_TAGS");
    275   if (tags == nullptr) {
    276     return;
    277   }
    278 
    279   std::vector<std::string> specs = Split(tags, " ");
    280   for (size_t i = 0; i < specs.size(); ++i) {
    281     // "tag-pattern:[vdiwefs]"
    282     std::string spec(specs[i]);
    283     if (spec.size() == 3 && StartsWith(spec, "*:")) {
    284       switch (spec[2]) {
    285         case 'v':
    286           gMinimumLogSeverity = VERBOSE;
    287           continue;
    288         case 'd':
    289           gMinimumLogSeverity = DEBUG;
    290           continue;
    291         case 'i':
    292           gMinimumLogSeverity = INFO;
    293           continue;
    294         case 'w':
    295           gMinimumLogSeverity = WARNING;
    296           continue;
    297         case 'e':
    298           gMinimumLogSeverity = ERROR;
    299           continue;
    300         case 'f':
    301           gMinimumLogSeverity = FATAL_WITHOUT_ABORT;
    302           continue;
    303         // liblog will even suppress FATAL if you say 's' for silent, but that's
    304         // crazy!
    305         case 's':
    306           gMinimumLogSeverity = FATAL_WITHOUT_ABORT;
    307           continue;
    308       }
    309     }
    310     LOG(FATAL) << "unsupported '" << spec << "' in ANDROID_LOG_TAGS (" << tags
    311                << ")";
    312   }
    313 }
    314 
    315 void SetLogger(LogFunction&& logger) {
    316   std::lock_guard<std::mutex> lock(LoggingLock());
    317   Logger() = std::move(logger);
    318 }
    319 
    320 void SetAborter(AbortFunction&& aborter) {
    321   std::lock_guard<std::mutex> lock(LoggingLock());
    322   Aborter() = std::move(aborter);
    323 }
    324 
    325 static const char* GetFileBasename(const char* file) {
    326   // We can't use basename(3) even on Unix because the Mac doesn't
    327   // have a non-modifying basename.
    328   const char* last_slash = strrchr(file, '/');
    329   if (last_slash != nullptr) {
    330     return last_slash + 1;
    331   }
    332 #if defined(_WIN32)
    333   const char* last_backslash = strrchr(file, '\\');
    334   if (last_backslash != nullptr) {
    335     return last_backslash + 1;
    336   }
    337 #endif
    338   return file;
    339 }
    340 
    341 // This indirection greatly reduces the stack impact of having lots of
    342 // checks/logging in a function.
    343 class LogMessageData {
    344  public:
    345   LogMessageData(const char* file, unsigned int line, LogId id,
    346                  LogSeverity severity, int error)
    347       : file_(GetFileBasename(file)),
    348         line_number_(line),
    349         id_(id),
    350         severity_(severity),
    351         error_(error) {
    352   }
    353 
    354   const char* GetFile() const {
    355     return file_;
    356   }
    357 
    358   unsigned int GetLineNumber() const {
    359     return line_number_;
    360   }
    361 
    362   LogSeverity GetSeverity() const {
    363     return severity_;
    364   }
    365 
    366   LogId GetId() const {
    367     return id_;
    368   }
    369 
    370   int GetError() const {
    371     return error_;
    372   }
    373 
    374   std::ostream& GetBuffer() {
    375     return buffer_;
    376   }
    377 
    378   std::string ToString() const {
    379     return buffer_.str();
    380   }
    381 
    382  private:
    383   std::ostringstream buffer_;
    384   const char* const file_;
    385   const unsigned int line_number_;
    386   const LogId id_;
    387   const LogSeverity severity_;
    388   const int error_;
    389 
    390   DISALLOW_COPY_AND_ASSIGN(LogMessageData);
    391 };
    392 
    393 LogMessage::LogMessage(const char* file, unsigned int line, LogId id,
    394                        LogSeverity severity, int error)
    395     : data_(new LogMessageData(file, line, id, severity, error)) {
    396 }
    397 
    398 LogMessage::~LogMessage() {
    399   // Check severity again. This is duplicate work wrt/ LOG macros, but not LOG_STREAM.
    400   if (!WOULD_LOG(data_->GetSeverity())) {
    401     return;
    402   }
    403 
    404   // Finish constructing the message.
    405   if (data_->GetError() != -1) {
    406     data_->GetBuffer() << ": " << strerror(data_->GetError());
    407   }
    408   std::string msg(data_->ToString());
    409 
    410   {
    411     // Do the actual logging with the lock held.
    412     std::lock_guard<std::mutex> lock(LoggingLock());
    413     if (msg.find('\n') == std::string::npos) {
    414       LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetId(),
    415               data_->GetSeverity(), msg.c_str());
    416     } else {
    417       msg += '\n';
    418       size_t i = 0;
    419       while (i < msg.size()) {
    420         size_t nl = msg.find('\n', i);
    421         msg[nl] = '\0';
    422         LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetId(),
    423                 data_->GetSeverity(), &msg[i]);
    424         // Undo the zero-termination so we can give the complete message to the aborter.
    425         msg[nl] = '\n';
    426         i = nl + 1;
    427       }
    428     }
    429   }
    430 
    431   // Abort if necessary.
    432   if (data_->GetSeverity() == FATAL) {
    433     Aborter()(msg.c_str());
    434   }
    435 }
    436 
    437 std::ostream& LogMessage::stream() {
    438   return data_->GetBuffer();
    439 }
    440 
    441 void LogMessage::LogLine(const char* file, unsigned int line, LogId id,
    442                          LogSeverity severity, const char* message) {
    443   const char* tag = ProgramInvocationName().c_str();
    444   Logger()(id, severity, tag, file, line, message);
    445 }
    446 
    447 LogSeverity GetMinimumLogSeverity() {
    448     return gMinimumLogSeverity;
    449 }
    450 
    451 LogSeverity SetMinimumLogSeverity(LogSeverity new_severity) {
    452   LogSeverity old_severity = gMinimumLogSeverity;
    453   gMinimumLogSeverity = new_severity;
    454   return old_severity;
    455 }
    456 
    457 ScopedLogSeverity::ScopedLogSeverity(LogSeverity new_severity) {
    458   old_ = SetMinimumLogSeverity(new_severity);
    459 }
    460 
    461 ScopedLogSeverity::~ScopedLogSeverity() {
    462   SetMinimumLogSeverity(old_);
    463 }
    464 
    465 }  // namespace base
    466 }  // namespace android
    467