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
36namespace art {
37
38LogVerbosity gLogVerbosity;
39
40unsigned int gAborting = 0;
41
42static LogSeverity gMinimumLogSeverity = INFO;
43static std::unique_ptr<std::string> gCmdLine;
44static std::unique_ptr<std::string> gProgramInvocationName;
45static 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__
51static constexpr bool kPrintInternalFatalDirectly = false;
52#else
53static constexpr bool kPrintInternalFatalDirectly = !kIsTargetBuild;
54#endif
55
56static bool PrintDirectly(LogSeverity severity) {
57  return kPrintInternalFatalDirectly && severity == INTERNAL_FATAL;
58}
59
60const char* GetCmdLine() {
61  return (gCmdLine.get() != nullptr) ? gCmdLine->c_str() : nullptr;
62}
63
64const char* ProgramInvocationName() {
65  return (gProgramInvocationName.get() != nullptr) ? gProgramInvocationName->c_str() : "art";
66}
67
68const char* ProgramInvocationShortName() {
69  return (gProgramInvocationShortName.get() != nullptr) ? gProgramInvocationShortName->c_str()
70                                                        : "art";
71}
72
73void 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.
139class 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
185LogMessage::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}
195LogMessage::~LogMessage() {
196  std::string msg;
197
198  if (!PrintDirectly(data_->GetSeverity()) && data_->GetSeverity() != LogSeverity::NONE) {
199    if (data_->GetSeverity() < gMinimumLogSeverity) {
200      return;  // No need to format something we're not going to output.
201    }
202
203    // Finish constructing the message.
204    if (data_->GetError() != -1) {
205      data_->GetBuffer() << ": " << strerror(data_->GetError());
206    }
207    msg = data_->ToString();
208
209    // Do the actual logging with the lock held.
210    {
211      MutexLock mu(Thread::Current(), *Locks::logging_lock_);
212      if (msg.find('\n') == std::string::npos) {
213        LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), msg.c_str());
214      } else {
215        msg += '\n';
216        size_t i = 0;
217        while (i < msg.size()) {
218          size_t nl = msg.find('\n', i);
219          msg[nl] = '\0';
220          LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), &msg[i]);
221          // Undo zero-termination, so we retain the complete message.
222          msg[nl] = '\n';
223          i = nl + 1;
224        }
225      }
226    }
227  }
228
229  // Abort if necessary.
230  if (data_->GetSeverity() == FATAL) {
231    Runtime::Abort(msg.c_str());
232  }
233}
234
235std::ostream& LogMessage::stream() {
236  if (PrintDirectly(data_->GetSeverity())) {
237    return std::cerr;
238  }
239  return data_->GetBuffer();
240}
241
242#ifdef __ANDROID__
243static const android_LogPriority kLogSeverityToAndroidLogPriority[] = {
244  ANDROID_LOG_VERBOSE,  // NONE, use verbose as stand-in, will never be printed.
245  ANDROID_LOG_VERBOSE, ANDROID_LOG_DEBUG, ANDROID_LOG_INFO, ANDROID_LOG_WARN,
246  ANDROID_LOG_ERROR, ANDROID_LOG_FATAL, ANDROID_LOG_FATAL
247};
248static_assert(arraysize(kLogSeverityToAndroidLogPriority) == INTERNAL_FATAL + 1,
249              "Mismatch in size of kLogSeverityToAndroidLogPriority and values in LogSeverity");
250#endif
251
252void LogMessage::LogLine(const char* file, unsigned int line, LogSeverity log_severity,
253                         const char* message) {
254  if (log_severity == LogSeverity::NONE) {
255    return;
256  }
257
258#ifdef __ANDROID__
259  const char* tag = ProgramInvocationShortName();
260  int priority = kLogSeverityToAndroidLogPriority[static_cast<size_t>(log_severity)];
261  if (priority == ANDROID_LOG_FATAL) {
262    LOG_PRI(priority, tag, "%s:%u] %s", file, line, message);
263  } else {
264    LOG_PRI(priority, tag, "%s", message);
265  }
266#else
267  static const char* log_characters = "NVDIWEFF";
268  CHECK_EQ(strlen(log_characters), INTERNAL_FATAL + 1U);
269  char severity = log_characters[log_severity];
270  fprintf(stderr, "%s %c %5d %5d %s:%u] %s\n",
271          ProgramInvocationShortName(), severity, getpid(), ::art::GetTid(), file, line, message);
272#endif
273}
274
275void LogMessage::LogLineLowStack(const char* file, unsigned int line, LogSeverity log_severity,
276                                 const char* message) {
277  if (log_severity == LogSeverity::NONE) {
278    return;
279  }
280
281#ifdef __ANDROID__
282  // Use android_writeLog() to avoid stack-based buffers used by android_printLog().
283  const char* tag = ProgramInvocationShortName();
284  int priority = kLogSeverityToAndroidLogPriority[static_cast<size_t>(log_severity)];
285  char* buf = nullptr;
286  size_t buf_size = 0u;
287  if (priority == ANDROID_LOG_FATAL) {
288    // Allocate buffer for snprintf(buf, buf_size, "%s:%u] %s", file, line, message) below.
289    // If allocation fails, fall back to printing only the message.
290    buf_size = strlen(file) + 1 /* ':' */ + std::numeric_limits<typeof(line)>::max_digits10 +
291        2 /* "] " */ + strlen(message) + 1 /* terminating 0 */;
292    buf = reinterpret_cast<char*>(malloc(buf_size));
293  }
294  if (buf != nullptr) {
295    snprintf(buf, buf_size, "%s:%u] %s", file, line, message);
296    android_writeLog(priority, tag, buf);
297    free(buf);
298  } else {
299    android_writeLog(priority, tag, message);
300  }
301#else
302  static constexpr char kLogCharacters[] = { 'N', 'V', 'D', 'I', 'W', 'E', 'F', 'F' };
303  static_assert(arraysize(kLogCharacters) == static_cast<size_t>(INTERNAL_FATAL) + 1,
304                "Wrong character array size");
305
306  const char* program_name = ProgramInvocationShortName();
307  TEMP_FAILURE_RETRY(write(STDERR_FILENO, program_name, strlen(program_name)));
308  TEMP_FAILURE_RETRY(write(STDERR_FILENO, " ", 1));
309  TEMP_FAILURE_RETRY(write(STDERR_FILENO, &kLogCharacters[static_cast<size_t>(log_severity)], 1));
310  TEMP_FAILURE_RETRY(write(STDERR_FILENO, " ", 1));
311  // TODO: pid and tid.
312  TEMP_FAILURE_RETRY(write(STDERR_FILENO, file, strlen(file)));
313  // TODO: line.
314  UNUSED(line);
315  TEMP_FAILURE_RETRY(write(STDERR_FILENO, "] ", 2));
316  TEMP_FAILURE_RETRY(write(STDERR_FILENO, message, strlen(message)));
317  TEMP_FAILURE_RETRY(write(STDERR_FILENO, "\n", 1));
318#endif
319}
320
321ScopedLogSeverity::ScopedLogSeverity(LogSeverity level) {
322  old_ = gMinimumLogSeverity;
323  gMinimumLogSeverity = level;
324}
325
326ScopedLogSeverity::~ScopedLogSeverity() {
327  gMinimumLogSeverity = old_;
328}
329
330}  // namespace art
331