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