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