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