Home | History | Annotate | Download | only in base 
      1 /*
      2  * Copyright (C) 2011 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 "logging.h"
     18 
     19 #include <iostream>
     20 #include <limits>
     21 #include <sstream>
     22 
     23 #include "base/mutex.h"
     24 #include "runtime.h"
     25 #include "thread-inl.h"
     26 #include "utils.h"
     27 
     28 // Headers for LogMessage::LogLine.
     29 #ifdef __ANDROID__
     30 #include "cutils/log.h"
     31 #else
     32 #include <sys/types.h>
     33 #include <unistd.h>
     34 #endif
     35 
     36 namespace art {
     37 
     38 LogVerbosity gLogVerbosity;
     39 
     40 unsigned int gAborting = 0;
     41 
     42 static LogSeverity gMinimumLogSeverity = INFO;
     43 static std::unique_ptr<std::string> gCmdLine;
     44 static std::unique_ptr<std::string> gProgramInvocationName;
     45 static std::unique_ptr<std::string> gProgramInvocationShortName;
     46 
     47 // Print INTERNAL_FATAL messages directly instead of at destruction time. This only works on the
     48 // host right now: for the device, a stream buf collating output into lines and calling LogLine or
     49 // lower-level logging is necessary.
     50 #ifdef __ANDROID__
     51 static constexpr bool kPrintInternalFatalDirectly = false;
     52 #else
     53 static constexpr bool kPrintInternalFatalDirectly = !kIsTargetBuild;
     54 #endif
     55 
     56 static bool PrintDirectly(LogSeverity severity) {
     57   return kPrintInternalFatalDirectly && severity == INTERNAL_FATAL;
     58 }
     59 
     60 const char* GetCmdLine() {
     61   return (gCmdLine.get() != nullptr) ? gCmdLine->c_str() : nullptr;
     62 }
     63 
     64 const char* ProgramInvocationName() {
     65   return (gProgramInvocationName.get() != nullptr) ? gProgramInvocationName->c_str() : "art";
     66 }
     67 
     68 const char* ProgramInvocationShortName() {
     69   return (gProgramInvocationShortName.get() != nullptr) ? gProgramInvocationShortName->c_str()
     70                                                         : "art";
     71 }
     72 
     73 void InitLogging(char* argv[]) {
     74   if (gCmdLine.get() != nullptr) {
     75     return;
     76   }
     77   // TODO: Move this to a more obvious InitART...
     78   Locks::Init();
     79 
     80   // Stash the command line for later use. We can use /proc/self/cmdline on Linux to recover this,
     81   // but we don't have that luxury on the Mac, and there are a couple of argv[0] variants that are
     82   // commonly used.
     83   if (argv != nullptr) {
     84     gCmdLine.reset(new std::string(argv[0]));
     85     for (size_t i = 1; argv[i] != nullptr; ++i) {
     86       gCmdLine->append(" ");
     87       gCmdLine->append(argv[i]);
     88     }
     89     gProgramInvocationName.reset(new std::string(argv[0]));
     90     const char* last_slash = strrchr(argv[0], '/');
     91     gProgramInvocationShortName.reset(new std::string((last_slash != nullptr) ? last_slash + 1
     92                                                                            : argv[0]));
     93   } else {
     94     // TODO: fall back to /proc/self/cmdline when argv is null on Linux.
     95     gCmdLine.reset(new std::string("<unset>"));
     96   }
     97   const char* tags = getenv("ANDROID_LOG_TAGS");
     98   if (tags == nullptr) {
     99     return;
    100   }
    101 
    102   std::vector<std::string> specs;
    103   Split(tags, ' ', &specs);
    104   for (size_t i = 0; i < specs.size(); ++i) {
    105     // "tag-pattern:[vdiwefs]"
    106     std::string spec(specs[i]);
    107     if (spec.size() == 3 && StartsWith(spec, "*:")) {
    108       switch (spec[2]) {
    109         case 'v':
    110           gMinimumLogSeverity = VERBOSE;
    111           continue;
    112         case 'd':
    113           gMinimumLogSeverity = DEBUG;
    114           continue;
    115         case 'i':
    116           gMinimumLogSeverity = INFO;
    117           continue;
    118         case 'w':
    119           gMinimumLogSeverity = WARNING;
    120           continue;
    121         case 'e':
    122           gMinimumLogSeverity = ERROR;
    123           continue;
    124         case 'f':
    125           gMinimumLogSeverity = FATAL;
    126           continue;
    127         // liblog will even suppress FATAL if you say 's' for silent, but that's crazy!
    128         case 's':
    129           gMinimumLogSeverity = FATAL;
    130           continue;
    131       }
    132     }
    133     LOG(FATAL) << "unsupported '" << spec << "' in ANDROID_LOG_TAGS (" << tags << ")";
    134   }
    135 }
    136 
    137 // This indirection greatly reduces the stack impact of having
    138 // lots of checks/logging in a function.
    139 class LogMessageData {
    140  public:
    141   LogMessageData(const char* file, unsigned int line, LogSeverity severity, int error)
    142       : file_(file),
    143         line_number_(line),
    144         severity_(severity),
    145         error_(error) {
    146     const char* last_slash = strrchr(file, '/');
    147     file = (last_slash == nullptr) ? file : last_slash + 1;
    148   }
    149 
    150   const char * GetFile() const {
    151     return file_;
    152   }
    153 
    154   unsigned int GetLineNumber() const {
    155     return line_number_;
    156   }
    157 
    158   LogSeverity GetSeverity() const {
    159     return severity_;
    160   }
    161 
    162   int GetError() const {
    163     return error_;
    164   }
    165 
    166   std::ostream& GetBuffer() {
    167     return buffer_;
    168   }
    169 
    170   std::string ToString() const {
    171     return buffer_.str();
    172   }
    173 
    174  private:
    175   std::ostringstream buffer_;
    176   const char* const file_;
    177   const unsigned int line_number_;
    178   const LogSeverity severity_;
    179   const int error_;
    180 
    181   DISALLOW_COPY_AND_ASSIGN(LogMessageData);
    182 };
    183 
    184 
    185 LogMessage::LogMessage(const char* file, unsigned int line, LogSeverity severity, int error)
    186   : data_(new LogMessageData(file, line, severity, error)) {
    187   if (PrintDirectly(severity)) {
    188     static constexpr char kLogCharacters[] = { 'N', 'V', 'D', 'I', 'W', 'E', 'F', 'F' };
    189     static_assert(arraysize(kLogCharacters) == static_cast<size_t>(INTERNAL_FATAL) + 1,
    190                   "Wrong character array size");
    191     stream() << ProgramInvocationShortName() << " " << kLogCharacters[static_cast<size_t>(severity)]
    192              << " " << getpid() << " " << ::art::GetTid() << " " << file << ":" <<  line << "]";
    193   }
    194 }
    195 LogMessage::~LogMessage() {
    196   if (!PrintDirectly(data_->GetSeverity()) && data_->GetSeverity() != LogSeverity::NONE) {
    197     if (data_->GetSeverity() < gMinimumLogSeverity) {
    198       return;  // No need to format something we're not going to output.
    199     }
    200 
    201     // Finish constructing the message.
    202     if (data_->GetError() != -1) {
    203       data_->GetBuffer() << ": " << strerror(data_->GetError());
    204     }
    205     std::string msg(data_->ToString());
    206 
    207     // Do the actual logging with the lock held.
    208     {
    209       MutexLock mu(Thread::Current(), *Locks::logging_lock_);
    210       if (msg.find('\n') == std::string::npos) {
    211         LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), msg.c_str());
    212       } else {
    213         msg += '\n';
    214         size_t i = 0;
    215         while (i < msg.size()) {
    216           size_t nl = msg.find('\n', i);
    217           msg[nl] = '\0';
    218           LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), &msg[i]);
    219           i = nl + 1;
    220         }
    221       }
    222     }
    223   }
    224 
    225   // Abort if necessary.
    226   if (data_->GetSeverity() == FATAL) {
    227     Runtime::Abort();
    228   }
    229 }
    230 
    231 std::ostream& LogMessage::stream() {
    232   if (PrintDirectly(data_->GetSeverity())) {
    233     return std::cerr;
    234   }
    235   return data_->GetBuffer();
    236 }
    237 
    238 #ifdef __ANDROID__
    239 static const android_LogPriority kLogSeverityToAndroidLogPriority[] = {
    240   ANDROID_LOG_VERBOSE,  // NONE, use verbose as stand-in, will never be printed.
    241   ANDROID_LOG_VERBOSE, ANDROID_LOG_DEBUG, ANDROID_LOG_INFO, ANDROID_LOG_WARN,
    242   ANDROID_LOG_ERROR, ANDROID_LOG_FATAL, ANDROID_LOG_FATAL
    243 };
    244 static_assert(arraysize(kLogSeverityToAndroidLogPriority) == INTERNAL_FATAL + 1,
    245               "Mismatch in size of kLogSeverityToAndroidLogPriority and values in LogSeverity");
    246 #endif
    247 
    248 void LogMessage::LogLine(const char* file, unsigned int line, LogSeverity log_severity,
    249                          const char* message) {
    250   if (log_severity == LogSeverity::NONE) {
    251     return;
    252   }
    253 
    254 #ifdef __ANDROID__
    255   const char* tag = ProgramInvocationShortName();
    256   int priority = kLogSeverityToAndroidLogPriority[static_cast<size_t>(log_severity)];
    257   if (priority == ANDROID_LOG_FATAL) {
    258     LOG_PRI(priority, tag, "%s:%u] %s", file, line, message);
    259   } else {
    260     LOG_PRI(priority, tag, "%s", message);
    261   }
    262 #else
    263   static const char* log_characters = "NVDIWEFF";
    264   CHECK_EQ(strlen(log_characters), INTERNAL_FATAL + 1U);
    265   char severity = log_characters[log_severity];
    266   fprintf(stderr, "%s %c %5d %5d %s:%u] %s\n",
    267           ProgramInvocationShortName(), severity, getpid(), ::art::GetTid(), file, line, message);
    268 #endif
    269 }
    270 
    271 void LogMessage::LogLineLowStack(const char* file, unsigned int line, LogSeverity log_severity,
    272                                  const char* message) {
    273   if (log_severity == LogSeverity::NONE) {
    274     return;
    275   }
    276 
    277 #ifdef __ANDROID__
    278   // Use android_writeLog() to avoid stack-based buffers used by android_printLog().
    279   const char* tag = ProgramInvocationShortName();
    280   int priority = kLogSeverityToAndroidLogPriority[static_cast<size_t>(log_severity)];
    281   char* buf = nullptr;
    282   size_t buf_size = 0u;
    283   if (priority == ANDROID_LOG_FATAL) {
    284     // Allocate buffer for snprintf(buf, buf_size, "%s:%u] %s", file, line, message) below.
    285     // If allocation fails, fall back to printing only the message.
    286     buf_size = strlen(file) + 1 /* ':' */ + std::numeric_limits<typeof(line)>::max_digits10 +
    287         2 /* "] " */ + strlen(message) + 1 /* terminating 0 */;
    288     buf = reinterpret_cast<char*>(malloc(buf_size));
    289   }
    290   if (buf != nullptr) {
    291     snprintf(buf, buf_size, "%s:%u] %s", file, line, message);
    292     android_writeLog(priority, tag, buf);
    293     free(buf);
    294   } else {
    295     android_writeLog(priority, tag, message);
    296   }
    297 #else
    298   static constexpr char kLogCharacters[] = { 'N', 'V', 'D', 'I', 'W', 'E', 'F', 'F' };
    299   static_assert(arraysize(kLogCharacters) == static_cast<size_t>(INTERNAL_FATAL) + 1,
    300                 "Wrong character array size");
    301 
    302   const char* program_name = ProgramInvocationShortName();
    303   TEMP_FAILURE_RETRY(write(STDERR_FILENO, program_name, strlen(program_name)));
    304   TEMP_FAILURE_RETRY(write(STDERR_FILENO, " ", 1));
    305   TEMP_FAILURE_RETRY(write(STDERR_FILENO, &kLogCharacters[static_cast<size_t>(log_severity)], 1));
    306   TEMP_FAILURE_RETRY(write(STDERR_FILENO, " ", 1));
    307   // TODO: pid and tid.
    308   TEMP_FAILURE_RETRY(write(STDERR_FILENO, file, strlen(file)));
    309   // TODO: line.
    310   UNUSED(line);
    311   TEMP_FAILURE_RETRY(write(STDERR_FILENO, "] ", 2));
    312   TEMP_FAILURE_RETRY(write(STDERR_FILENO, message, strlen(message)));
    313   TEMP_FAILURE_RETRY(write(STDERR_FILENO, "\n", 1));
    314 #endif
    315 }
    316 
    317 ScopedLogSeverity::ScopedLogSeverity(LogSeverity level) {
    318   old_ = gMinimumLogSeverity;
    319   gMinimumLogSeverity = level;
    320 }
    321 
    322 ScopedLogSeverity::~ScopedLogSeverity() {
    323   gMinimumLogSeverity = old_;
    324 }
    325 
    326 }  // namespace art
    327