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
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 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 }
~LogMessage()195 LogMessage::~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
stream()235 std::ostream& LogMessage::stream() {
236 if (PrintDirectly(data_->GetSeverity())) {
237 return std::cerr;
238 }
239 return data_->GetBuffer();
240 }
241
242 #ifdef __ANDROID__
243 static 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 };
248 static_assert(arraysize(kLogSeverityToAndroidLogPriority) == INTERNAL_FATAL + 1,
249 "Mismatch in size of kLogSeverityToAndroidLogPriority and values in LogSeverity");
250 #endif
251
LogLine(const char * file,unsigned int line,LogSeverity log_severity,const char * message)252 void 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
LogLineLowStack(const char * file,unsigned int line,LogSeverity log_severity,const char * message)275 void 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
ScopedLogSeverity(LogSeverity level)321 ScopedLogSeverity::ScopedLogSeverity(LogSeverity level) {
322 old_ = gMinimumLogSeverity;
323 gMinimumLogSeverity = level;
324 }
325
~ScopedLogSeverity()326 ScopedLogSeverity::~ScopedLogSeverity() {
327 gMinimumLogSeverity = old_;
328 }
329
330 } // namespace art
331