1 /* 2 * Copyright (C) 2008-2014 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 * Intercepts log messages intended for the Android log device. 18 * Messages are printed to stderr. 19 */ 20 #include <ctype.h> 21 #include <errno.h> 22 #include <fcntl.h> 23 #if !defined(_WIN32) 24 #include <pthread.h> 25 #endif 26 #include <stdint.h> 27 #include <stdio.h> 28 #include <stdlib.h> 29 #include <string.h> 30 #include <time.h> 31 32 #include <android/log.h> 33 #include <log/uio.h> 34 35 #include "fake_log_device.h" 36 #include "log_portability.h" 37 38 #define kMaxTagLen 16 /* from the long-dead utils/Log.cpp */ 39 40 #define kTagSetSize 16 /* arbitrary */ 41 42 #if 0 43 #define TRACE(...) printf("fake_log_device: " __VA_ARGS__) 44 #else 45 #define TRACE(...) ((void)0) 46 #endif 47 48 /* from the long-dead utils/Log.cpp */ 49 typedef enum { 50 FORMAT_OFF = 0, 51 FORMAT_BRIEF, 52 FORMAT_PROCESS, 53 FORMAT_TAG, 54 FORMAT_THREAD, 55 FORMAT_RAW, 56 FORMAT_TIME, 57 FORMAT_THREADTIME, 58 FORMAT_LONG 59 } LogFormat; 60 61 /* 62 * Log driver state. 63 */ 64 typedef struct LogState { 65 /* the fake fd that's seen by the user */ 66 int fakeFd; 67 68 /* a printable name for this fake device */ 69 char debugName[sizeof("/dev/log/security")]; 70 71 /* nonzero if this is a binary log */ 72 int isBinary; 73 74 /* global minimum priority */ 75 int globalMinPriority; 76 77 /* output format */ 78 LogFormat outputFormat; 79 80 /* tags and priorities */ 81 struct { 82 char tag[kMaxTagLen]; 83 int minPriority; 84 } tagSet[kTagSetSize]; 85 } LogState; 86 87 #if !defined(_WIN32) 88 /* 89 * Locking. Since we're emulating a device, we need to be prepared 90 * to have multiple callers at the same time. This lock is used 91 * to both protect the fd list and to prevent LogStates from being 92 * freed out from under a user. 93 */ 94 static pthread_mutex_t fakeLogDeviceLock = PTHREAD_MUTEX_INITIALIZER; 95 96 static void lock() { 97 /* 98 * If we trigger a signal handler in the middle of locked activity and the 99 * signal handler logs a message, we could get into a deadlock state. 100 */ 101 pthread_mutex_lock(&fakeLogDeviceLock); 102 } 103 104 static void unlock() { 105 pthread_mutex_unlock(&fakeLogDeviceLock); 106 } 107 108 #else // !defined(_WIN32) 109 110 #define lock() ((void)0) 111 #define unlock() ((void)0) 112 113 #endif // !defined(_WIN32) 114 115 /* 116 * File descriptor management. 117 */ 118 #define FAKE_FD_BASE 10000 119 #define MAX_OPEN_LOGS 8 120 static LogState openLogTable[MAX_OPEN_LOGS]; 121 122 /* 123 * Allocate an fd and associate a new LogState with it. 124 * The fd is available via the fakeFd field of the return value. 125 */ 126 static LogState* createLogState() { 127 size_t i; 128 129 for (i = 0; i < (sizeof(openLogTable) / sizeof(openLogTable[0])); i++) { 130 if (openLogTable[i].fakeFd == 0) { 131 openLogTable[i].fakeFd = FAKE_FD_BASE + i; 132 return &openLogTable[i]; 133 } 134 } 135 return NULL; 136 } 137 138 /* 139 * Translate an fd to a LogState. 140 */ 141 static LogState* fdToLogState(int fd) { 142 if (fd >= FAKE_FD_BASE && fd < FAKE_FD_BASE + MAX_OPEN_LOGS) { 143 return &openLogTable[fd - FAKE_FD_BASE]; 144 } 145 return NULL; 146 } 147 148 /* 149 * Unregister the fake fd and free the memory it pointed to. 150 */ 151 static void deleteFakeFd(int fd) { 152 LogState* ls; 153 154 lock(); 155 156 ls = fdToLogState(fd); 157 if (ls != NULL) { 158 memset(&openLogTable[fd - FAKE_FD_BASE], 0, sizeof(openLogTable[0])); 159 } 160 161 unlock(); 162 } 163 164 /* 165 * Configure logging based on ANDROID_LOG_TAGS environment variable. We 166 * need to parse a string that looks like 167 * 168 * *:v jdwp:d dalvikvm:d dalvikvm-gc:i dalvikvmi:i 169 * 170 * The tag (or '*' for the global level) comes first, followed by a colon 171 * and a letter indicating the minimum priority level we're expected to log. 172 * This can be used to reveal or conceal logs with specific tags. 173 * 174 * We also want to check ANDROID_PRINTF_LOG to determine how the output 175 * will look. 176 */ 177 static void configureInitialState(const char* pathName, LogState* logState) { 178 static const int kDevLogLen = sizeof("/dev/log/") - 1; 179 180 strncpy(logState->debugName, pathName, sizeof(logState->debugName)); 181 logState->debugName[sizeof(logState->debugName) - 1] = '\0'; 182 183 /* identify binary logs */ 184 if (!strcmp(pathName + kDevLogLen, "events") || 185 !strcmp(pathName + kDevLogLen, "security")) { 186 logState->isBinary = 1; 187 } 188 189 /* global min priority defaults to "info" level */ 190 logState->globalMinPriority = ANDROID_LOG_INFO; 191 192 /* 193 * This is based on the the long-dead utils/Log.cpp code. 194 */ 195 const char* tags = getenv("ANDROID_LOG_TAGS"); 196 TRACE("Found ANDROID_LOG_TAGS='%s'\n", tags); 197 if (tags != NULL) { 198 int entry = 0; 199 200 while (*tags != '\0') { 201 char tagName[kMaxTagLen]; 202 int i, minPrio; 203 204 while (isspace(*tags)) tags++; 205 206 i = 0; 207 while (*tags != '\0' && !isspace(*tags) && *tags != ':' && 208 i < kMaxTagLen) { 209 tagName[i++] = *tags++; 210 } 211 if (i == kMaxTagLen) { 212 TRACE("ERROR: env tag too long (%d chars max)\n", kMaxTagLen - 1); 213 return; 214 } 215 tagName[i] = '\0'; 216 217 /* default priority, if there's no ":" part; also zero out '*' */ 218 minPrio = ANDROID_LOG_VERBOSE; 219 if (tagName[0] == '*' && tagName[1] == '\0') { 220 minPrio = ANDROID_LOG_DEBUG; 221 tagName[0] = '\0'; 222 } 223 224 if (*tags == ':') { 225 tags++; 226 if (*tags >= '0' && *tags <= '9') { 227 if (*tags >= ('0' + ANDROID_LOG_SILENT)) 228 minPrio = ANDROID_LOG_VERBOSE; 229 else 230 minPrio = *tags - '\0'; 231 } else { 232 switch (*tags) { 233 case 'v': 234 minPrio = ANDROID_LOG_VERBOSE; 235 break; 236 case 'd': 237 minPrio = ANDROID_LOG_DEBUG; 238 break; 239 case 'i': 240 minPrio = ANDROID_LOG_INFO; 241 break; 242 case 'w': 243 minPrio = ANDROID_LOG_WARN; 244 break; 245 case 'e': 246 minPrio = ANDROID_LOG_ERROR; 247 break; 248 case 'f': 249 minPrio = ANDROID_LOG_FATAL; 250 break; 251 case 's': 252 minPrio = ANDROID_LOG_SILENT; 253 break; 254 default: 255 minPrio = ANDROID_LOG_DEFAULT; 256 break; 257 } 258 } 259 260 tags++; 261 if (*tags != '\0' && !isspace(*tags)) { 262 TRACE("ERROR: garbage in tag env; expected whitespace\n"); 263 TRACE(" env='%s'\n", tags); 264 return; 265 } 266 } 267 268 if (tagName[0] == 0) { 269 logState->globalMinPriority = minPrio; 270 TRACE("+++ global min prio %d\n", logState->globalMinPriority); 271 } else { 272 logState->tagSet[entry].minPriority = minPrio; 273 strcpy(logState->tagSet[entry].tag, tagName); 274 TRACE("+++ entry %d: %s:%d\n", entry, logState->tagSet[entry].tag, 275 logState->tagSet[entry].minPriority); 276 entry++; 277 } 278 } 279 } 280 281 /* 282 * Taken from the long-dead utils/Log.cpp 283 */ 284 const char* fstr = getenv("ANDROID_PRINTF_LOG"); 285 LogFormat format; 286 if (fstr == NULL) { 287 format = FORMAT_BRIEF; 288 } else { 289 if (strcmp(fstr, "brief") == 0) 290 format = FORMAT_BRIEF; 291 else if (strcmp(fstr, "process") == 0) 292 format = FORMAT_PROCESS; 293 else if (strcmp(fstr, "tag") == 0) 294 format = FORMAT_PROCESS; 295 else if (strcmp(fstr, "thread") == 0) 296 format = FORMAT_PROCESS; 297 else if (strcmp(fstr, "raw") == 0) 298 format = FORMAT_PROCESS; 299 else if (strcmp(fstr, "time") == 0) 300 format = FORMAT_PROCESS; 301 else if (strcmp(fstr, "long") == 0) 302 format = FORMAT_PROCESS; 303 else 304 format = (LogFormat)atoi(fstr); // really?! 305 } 306 307 logState->outputFormat = format; 308 } 309 310 /* 311 * Return a human-readable string for the priority level. Always returns 312 * a valid string. 313 */ 314 static const char* getPriorityString(int priority) { 315 /* the first character of each string should be unique */ 316 static const char* priorityStrings[] = { "Verbose", "Debug", "Info", 317 "Warn", "Error", "Assert" }; 318 int idx; 319 320 idx = (int)priority - (int)ANDROID_LOG_VERBOSE; 321 if (idx < 0 || 322 idx >= (int)(sizeof(priorityStrings) / sizeof(priorityStrings[0]))) 323 return "?unknown?"; 324 return priorityStrings[idx]; 325 } 326 327 #if defined(_WIN32) 328 /* 329 * WIN32 does not have writev(). 330 * Make up something to replace it. 331 */ 332 static ssize_t fake_writev(int fd, const struct iovec* iov, int iovcnt) { 333 ssize_t result = 0; 334 const struct iovec* end = iov + iovcnt; 335 for (; iov < end; iov++) { 336 ssize_t w = write(fd, iov->iov_base, iov->iov_len); 337 if (w != (ssize_t)iov->iov_len) { 338 if (w < 0) return w; 339 return result + w; 340 } 341 result += w; 342 } 343 return result; 344 } 345 346 #define writev fake_writev 347 #endif 348 349 /* 350 * Write a filtered log message to stderr. 351 * 352 * Log format parsing taken from the long-dead utils/Log.cpp. 353 */ 354 static void showLog(LogState* state, int logPrio, const char* tag, 355 const char* msg) { 356 #if !defined(_WIN32) 357 struct tm tmBuf; 358 #endif 359 struct tm* ptm; 360 char timeBuf[32]; 361 char prefixBuf[128], suffixBuf[128]; 362 char priChar; 363 time_t when; 364 #if !defined(_WIN32) 365 pid_t pid, tid; 366 #else 367 uint32_t pid, tid; 368 #endif 369 370 TRACE("LOG %d: %s %s", logPrio, tag, msg); 371 372 priChar = getPriorityString(logPrio)[0]; 373 when = time(NULL); 374 pid = tid = getpid(); // find gettid()? 375 376 /* 377 * Get the current date/time in pretty form 378 * 379 * It's often useful when examining a log with "less" to jump to 380 * a specific point in the file by searching for the date/time stamp. 381 * For this reason it's very annoying to have regexp meta characters 382 * in the time stamp. Don't use forward slashes, parenthesis, 383 * brackets, asterisks, or other special chars here. 384 */ 385 #if !defined(_WIN32) 386 ptm = localtime_r(&when, &tmBuf); 387 #else 388 ptm = localtime(&when); 389 #endif 390 // strftime(timeBuf, sizeof(timeBuf), "%Y-%m-%d %H:%M:%S", ptm); 391 strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm); 392 393 /* 394 * Construct a buffer containing the log header and log message. 395 */ 396 size_t prefixLen, suffixLen; 397 398 switch (state->outputFormat) { 399 case FORMAT_TAG: 400 prefixLen = 401 snprintf(prefixBuf, sizeof(prefixBuf), "%c/%-8s: ", priChar, tag); 402 strcpy(suffixBuf, "\n"); 403 suffixLen = 1; 404 break; 405 case FORMAT_PROCESS: 406 prefixLen = 407 snprintf(prefixBuf, sizeof(prefixBuf), "%c(%5d) ", priChar, pid); 408 suffixLen = snprintf(suffixBuf, sizeof(suffixBuf), " (%s)\n", tag); 409 break; 410 case FORMAT_THREAD: 411 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf), "%c(%5d:%5d) ", 412 priChar, pid, tid); 413 strcpy(suffixBuf, "\n"); 414 suffixLen = 1; 415 break; 416 case FORMAT_RAW: 417 prefixBuf[0] = 0; 418 prefixLen = 0; 419 strcpy(suffixBuf, "\n"); 420 suffixLen = 1; 421 break; 422 case FORMAT_TIME: 423 prefixLen = 424 snprintf(prefixBuf, sizeof(prefixBuf), "%s %-8s\n\t", timeBuf, tag); 425 strcpy(suffixBuf, "\n"); 426 suffixLen = 1; 427 break; 428 case FORMAT_THREADTIME: 429 prefixLen = 430 snprintf(prefixBuf, sizeof(prefixBuf), "%s %5d %5d %c %-8s \n\t", 431 timeBuf, pid, tid, priChar, tag); 432 strcpy(suffixBuf, "\n"); 433 suffixLen = 1; 434 break; 435 case FORMAT_LONG: 436 prefixLen = 437 snprintf(prefixBuf, sizeof(prefixBuf), "[ %s %5d:%5d %c/%-8s ]\n", 438 timeBuf, pid, tid, priChar, tag); 439 strcpy(suffixBuf, "\n\n"); 440 suffixLen = 2; 441 break; 442 default: 443 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf), 444 "%c/%-8s(%5d): ", priChar, tag, pid); 445 strcpy(suffixBuf, "\n"); 446 suffixLen = 1; 447 break; 448 } 449 450 /* 451 * Figure out how many lines there will be. 452 */ 453 const char* end = msg + strlen(msg); 454 size_t numLines = 0; 455 const char* p = msg; 456 while (p < end) { 457 if (*p++ == '\n') numLines++; 458 } 459 if (p > msg && *(p - 1) != '\n') { 460 numLines++; 461 } 462 463 /* 464 * Create an array of iovecs large enough to write all of 465 * the lines with a prefix and a suffix. 466 */ 467 const size_t INLINE_VECS = 64; 468 const size_t MAX_LINES = ((size_t)~0) / (3 * sizeof(struct iovec*)); 469 struct iovec stackVec[INLINE_VECS]; 470 struct iovec* vec = stackVec; 471 size_t numVecs; 472 473 if (numLines > MAX_LINES) numLines = MAX_LINES; 474 475 numVecs = numLines * 3; // 3 iovecs per line. 476 if (numVecs > INLINE_VECS) { 477 vec = (struct iovec*)malloc(sizeof(struct iovec) * numVecs); 478 if (vec == NULL) { 479 msg = "LOG: write failed, no memory"; 480 numVecs = INLINE_VECS; 481 numLines = numVecs / 3; 482 vec = stackVec; 483 } 484 } 485 486 /* 487 * Fill in the iovec pointers. 488 */ 489 p = msg; 490 struct iovec* v = vec; 491 int totalLen = 0; 492 while (numLines > 0 && p < end) { 493 if (prefixLen > 0) { 494 v->iov_base = prefixBuf; 495 v->iov_len = prefixLen; 496 totalLen += prefixLen; 497 v++; 498 } 499 const char* start = p; 500 while (p < end && *p != '\n') { 501 p++; 502 } 503 if ((p - start) > 0) { 504 v->iov_base = (void*)start; 505 v->iov_len = p - start; 506 totalLen += p - start; 507 v++; 508 } 509 if (*p == '\n') p++; 510 if (suffixLen > 0) { 511 v->iov_base = suffixBuf; 512 v->iov_len = suffixLen; 513 totalLen += suffixLen; 514 v++; 515 } 516 numLines -= 1; 517 } 518 519 /* 520 * Write the entire message to the log file with a single writev() call. 521 * We need to use this rather than a collection of printf()s on a FILE* 522 * because of multi-threading and multi-process issues. 523 * 524 * If the file was not opened with O_APPEND, this will produce interleaved 525 * output when called on the same file from multiple processes. 526 * 527 * If the file descriptor is actually a network socket, the writev() 528 * call may return with a partial write. Putting the writev() call in 529 * a loop can result in interleaved data. This can be alleviated 530 * somewhat by wrapping the writev call in the Mutex. 531 */ 532 533 for (;;) { 534 int cc = writev(fileno(stderr), vec, v - vec); 535 536 if (cc == totalLen) break; 537 538 if (cc < 0) { 539 if (errno == EINTR) continue; 540 541 /* can't really log the failure; for now, throw out a stderr */ 542 fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno); 543 break; 544 } else { 545 /* shouldn't happen when writing to file or tty */ 546 fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", cc, totalLen); 547 break; 548 } 549 } 550 551 /* if we allocated storage for the iovecs, free it */ 552 if (vec != stackVec) free(vec); 553 } 554 555 /* 556 * Receive a log message. We happen to know that "vector" has three parts: 557 * 558 * priority (1 byte) 559 * tag (N bytes -- null-terminated ASCII string) 560 * message (N bytes -- null-terminated ASCII string) 561 */ 562 LIBLOG_HIDDEN ssize_t fakeLogWritev(int fd, const struct iovec* vector, 563 int count) { 564 LogState* state; 565 566 /* Make sure that no-one frees the LogState while we're using it. 567 * Also guarantees that only one thread is in showLog() at a given 568 * time (if it matters). 569 */ 570 lock(); 571 572 state = fdToLogState(fd); 573 if (state == NULL) { 574 errno = EBADF; 575 goto error; 576 } 577 578 if (state->isBinary) { 579 TRACE("%s: ignoring binary log\n", state->debugName); 580 goto bail; 581 } 582 583 if (count != 3) { 584 TRACE("%s: writevLog with count=%d not expected\n", state->debugName, count); 585 goto error; 586 } 587 588 /* pull out the three fields */ 589 int logPrio = *(const char*)vector[0].iov_base; 590 const char* tag = (const char*)vector[1].iov_base; 591 const char* msg = (const char*)vector[2].iov_base; 592 593 /* see if this log tag is configured */ 594 int i; 595 int minPrio = state->globalMinPriority; 596 for (i = 0; i < kTagSetSize; i++) { 597 if (state->tagSet[i].minPriority == ANDROID_LOG_UNKNOWN) 598 break; /* reached end of configured values */ 599 600 if (strcmp(state->tagSet[i].tag, tag) == 0) { 601 // TRACE("MATCH tag '%s'\n", tag); 602 minPrio = state->tagSet[i].minPriority; 603 break; 604 } 605 } 606 607 if (logPrio >= minPrio) { 608 showLog(state, logPrio, tag, msg); 609 } else { 610 // TRACE("+++ NOLOG(%d): %s %s", logPrio, tag, msg); 611 } 612 613 bail: 614 unlock(); 615 int len = 0; 616 for (i = 0; i < count; ++i) { 617 len += vector[i].iov_len; 618 } 619 return len; 620 621 error: 622 unlock(); 623 return -1; 624 } 625 626 /* 627 * Free up our state and close the fake descriptor. 628 * 629 * The logger API has no means or need to 'stop' or 'close' using the logs, 630 * and as such, there is no way for that 'stop' or 'close' to translate into 631 * a close operation to the fake log handler. fakeLogClose is provided for 632 * completeness only. 633 * 634 * We have no intention of adding a log close operation as it would complicate 635 * every user of the logging API with no gain since the only valid place to 636 * call is in the exit handler. Logging can continue in the exit handler to 637 * help debug HOST tools ... 638 */ 639 LIBLOG_HIDDEN int fakeLogClose(int fd) { 640 deleteFakeFd(fd); 641 return 0; 642 } 643 644 /* 645 * Open a log output device and return a fake fd. 646 */ 647 LIBLOG_HIDDEN int fakeLogOpen(const char* pathName) { 648 LogState* logState; 649 int fd = -1; 650 651 lock(); 652 653 logState = createLogState(); 654 if (logState != NULL) { 655 configureInitialState(pathName, logState); 656 fd = logState->fakeFd; 657 } else { 658 errno = ENFILE; 659 } 660 661 unlock(); 662 663 return fd; 664 } 665 666 LIBLOG_HIDDEN ssize_t __send_log_msg(char* buf __unused, 667 size_t buf_size __unused) { 668 return -ENODEV; 669 } 670 671 LIBLOG_ABI_PUBLIC int __android_log_is_loggable(int prio, 672 const char* tag __unused, 673 int def) { 674 int logLevel = def; 675 return logLevel >= 0 && prio >= logLevel; 676 } 677 678 LIBLOG_ABI_PUBLIC int __android_log_is_loggable_len(int prio, 679 const char* tag __unused, 680 size_t len __unused, 681 int def) { 682 int logLevel = def; 683 return logLevel >= 0 && prio >= logLevel; 684 } 685 686 LIBLOG_ABI_PRIVATE int __android_log_is_debuggable() { 687 return 1; 688 } 689