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 HAVE_ANDROID_OS
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 HAVE_ANDROID_OS
51 static constexpr bool kPrintInternalFatalDirectly = false;
52 #else
53 static constexpr bool kPrintInternalFatalDirectly = !kIsTargetBuild;
54 #endif
55 
PrintDirectly(LogSeverity severity)56 static bool PrintDirectly(LogSeverity severity) {
57   return kPrintInternalFatalDirectly && severity == INTERNAL_FATAL;
58 }
59 
GetCmdLine()60 const char* GetCmdLine() {
61   return (gCmdLine.get() != nullptr) ? gCmdLine->c_str() : nullptr;
62 }
63 
ProgramInvocationName()64 const char* ProgramInvocationName() {
65   return (gProgramInvocationName.get() != nullptr) ? gProgramInvocationName->c_str() : "art";
66 }
67 
ProgramInvocationShortName()68 const char* ProgramInvocationShortName() {
69   return (gProgramInvocationShortName.get() != nullptr) ? gProgramInvocationShortName->c_str()
70                                                         : "art";
71 }
72 
InitLogging(char * argv[])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:
LogMessageData(const char * file,unsigned int line,LogSeverity severity,int error)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 
GetFile() const150   const char * GetFile() const {
151     return file_;
152   }
153 
GetLineNumber() const154   unsigned int GetLineNumber() const {
155     return line_number_;
156   }
157 
GetSeverity() const158   LogSeverity GetSeverity() const {
159     return severity_;
160   }
161 
GetError() const162   int GetError() const {
163     return error_;
164   }
165 
GetBuffer()166   std::ostream& GetBuffer() {
167     return buffer_;
168   }
169 
ToString() const170   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 
LogMessage(const char * file,unsigned int line,LogSeverity severity,int error)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 const char* log_characters = "VDIWEFF";
189     CHECK_EQ(strlen(log_characters), INTERNAL_FATAL + 1U);
190     stream() << ProgramInvocationShortName() << " " << log_characters[static_cast<size_t>(severity)]
191              << " " << getpid() << " " << ::art::GetTid() << " " << file << ":" <<  line << "]";
192   }
193 }
~LogMessage()194 LogMessage::~LogMessage() {
195   if (!PrintDirectly(data_->GetSeverity())) {
196     if (data_->GetSeverity() < gMinimumLogSeverity) {
197       return;  // No need to format something we're not going to output.
198     }
199 
200     // Finish constructing the message.
201     if (data_->GetError() != -1) {
202       data_->GetBuffer() << ": " << strerror(data_->GetError());
203     }
204     std::string msg(data_->ToString());
205 
206     // Do the actual logging with the lock held.
207     {
208       MutexLock mu(Thread::Current(), *Locks::logging_lock_);
209       if (msg.find('\n') == std::string::npos) {
210         LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), msg.c_str());
211       } else {
212         msg += '\n';
213         size_t i = 0;
214         while (i < msg.size()) {
215           size_t nl = msg.find('\n', i);
216           msg[nl] = '\0';
217           LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), &msg[i]);
218           i = nl + 1;
219         }
220       }
221     }
222   }
223 
224   // Abort if necessary.
225   if (data_->GetSeverity() == FATAL) {
226     Runtime::Abort();
227   }
228 }
229 
stream()230 std::ostream& LogMessage::stream() {
231   if (PrintDirectly(data_->GetSeverity())) {
232     return std::cerr;
233   }
234   return data_->GetBuffer();
235 }
236 
237 #ifdef HAVE_ANDROID_OS
238 static const android_LogPriority kLogSeverityToAndroidLogPriority[] = {
239   ANDROID_LOG_VERBOSE, ANDROID_LOG_DEBUG, ANDROID_LOG_INFO, ANDROID_LOG_WARN,
240   ANDROID_LOG_ERROR, ANDROID_LOG_FATAL, ANDROID_LOG_FATAL
241 };
242 static_assert(arraysize(kLogSeverityToAndroidLogPriority) == INTERNAL_FATAL + 1,
243               "Mismatch in size of kLogSeverityToAndroidLogPriority and values in LogSeverity");
244 #endif
245 
LogLine(const char * file,unsigned int line,LogSeverity log_severity,const char * message)246 void LogMessage::LogLine(const char* file, unsigned int line, LogSeverity log_severity,
247                          const char* message) {
248 #ifdef HAVE_ANDROID_OS
249   const char* tag = ProgramInvocationShortName();
250   int priority = kLogSeverityToAndroidLogPriority[log_severity];
251   if (priority == ANDROID_LOG_FATAL) {
252     LOG_PRI(priority, tag, "%s:%u] %s", file, line, message);
253   } else {
254     LOG_PRI(priority, tag, "%s", message);
255   }
256 #else
257   static const char* log_characters = "VDIWEFF";
258   CHECK_EQ(strlen(log_characters), INTERNAL_FATAL + 1U);
259   char severity = log_characters[log_severity];
260   fprintf(stderr, "%s %c %5d %5d %s:%u] %s\n",
261           ProgramInvocationShortName(), severity, getpid(), ::art::GetTid(), file, line, message);
262 #endif
263 }
264 
LogLineLowStack(const char * file,unsigned int line,LogSeverity log_severity,const char * message)265 void LogMessage::LogLineLowStack(const char* file, unsigned int line, LogSeverity log_severity,
266                                  const char* message) {
267 #ifdef HAVE_ANDROID_OS
268   // Use android_writeLog() to avoid stack-based buffers used by android_printLog().
269   const char* tag = ProgramInvocationShortName();
270   int priority = kLogSeverityToAndroidLogPriority[log_severity];
271   char* buf = nullptr;
272   size_t buf_size = 0u;
273   if (priority == ANDROID_LOG_FATAL) {
274     // Allocate buffer for snprintf(buf, buf_size, "%s:%u] %s", file, line, message) below.
275     // If allocation fails, fall back to printing only the message.
276     buf_size = strlen(file) + 1 /* ':' */ + std::numeric_limits<typeof(line)>::max_digits10 +
277         2 /* "] " */ + strlen(message) + 1 /* terminating 0 */;
278     buf = reinterpret_cast<char*>(malloc(buf_size));
279   }
280   if (buf != nullptr) {
281     snprintf(buf, buf_size, "%s:%u] %s", file, line, message);
282     android_writeLog(priority, tag, buf);
283     free(buf);
284   } else {
285     android_writeLog(priority, tag, message);
286   }
287 #else
288   static const char* log_characters = "VDIWEFF";
289   CHECK_EQ(strlen(log_characters), INTERNAL_FATAL + 1U);
290 
291   const char* program_name = ProgramInvocationShortName();
292   write(STDERR_FILENO, program_name, strlen(program_name));
293   write(STDERR_FILENO, " ", 1);
294   write(STDERR_FILENO, &log_characters[log_severity], 1);
295   write(STDERR_FILENO, " ", 1);
296   // TODO: pid and tid.
297   write(STDERR_FILENO, file, strlen(file));
298   // TODO: line.
299   UNUSED(line);
300   write(STDERR_FILENO, "] ", 2);
301   write(STDERR_FILENO, message, strlen(message));
302   write(STDERR_FILENO, "\n", 1);
303 #endif
304 }
305 
ScopedLogSeverity(LogSeverity level)306 ScopedLogSeverity::ScopedLogSeverity(LogSeverity level) {
307   old_ = gMinimumLogSeverity;
308   gMinimumLogSeverity = level;
309 }
310 
~ScopedLogSeverity()311 ScopedLogSeverity::~ScopedLogSeverity() {
312   gMinimumLogSeverity = old_;
313 }
314 
315 }  // namespace art
316