system/core/liblog/fake_log_device.c

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