Home | History | Annotate | Download | only in wrapsim 
      1 /*
      2  * Copyright 2007 The Android Open Source Project
      3  *
      4  * Log devices.  We want to filter and display messages, with separate
      5  * treatment for "debug" and "event" logs.
      6  *
      7  * All messages are just dumped to stderr.
      8  */
      9 #include "Common.h"
     10 
     11 #include "cutils/logd.h"
     12 
     13 #include <stdlib.h>
     14 #include <string.h>
     15 #include <ctype.h>
     16 
     17 #include <fcntl.h>
     18 
     19 #define kMaxTagLen  16      /* from utils/Log.cpp */
     20 
     21 #define kTagSetSize 16      /* arbitrary */
     22 
     23 /* from utils/Log.cpp */
     24 typedef enum {
     25     FORMAT_OFF = 0,
     26     FORMAT_BRIEF,
     27     FORMAT_PROCESS,
     28     FORMAT_TAG,
     29     FORMAT_THREAD,
     30     FORMAT_RAW,
     31     FORMAT_TIME,
     32     FORMAT_LONG
     33 } LogFormat;
     34 
     35 
     36 /*
     37  * Log driver state.
     38  */
     39 typedef struct LogState {
     40     /* nonzero if this is a binary log */
     41     int     isBinary;
     42 
     43     /* global minimum priority */
     44     int     globalMinPriority;
     45 
     46     /* output format */
     47     LogFormat outputFormat;
     48 
     49     /* tags and priorities */
     50     struct {
     51         char    tag[kMaxTagLen];
     52         int     minPriority;
     53     } tagSet[kTagSetSize];
     54 } LogState;
     55 
     56 
     57 /*
     58  * Configure logging based on ANDROID_LOG_TAGS environment variable.  We
     59  * need to parse a string that looks like
     60  *
     61  *  '*:v jdwp:d dalvikvm:d dalvikvm-gc:i dalvikvmi:i
     62  *
     63  * The tag (or '*' for the global level) comes first, followed by a colon
     64  * and a letter indicating the minimum priority level we're expected to log.
     65  * This can be used to reveal or conceal logs with specific tags.
     66  *
     67  * We also want to check ANDROID_PRINTF_LOG to determine how the output
     68  * will look.
     69  */
     70 static void configureInitialState(const char* pathName, LogState* logState)
     71 {
     72     static const int kDevLogLen = 9;    /* strlen("/dev/log/") */
     73 
     74     /* identify binary logs */
     75     if (strcmp(pathName + kDevLogLen, "events") == 0) {
     76         logState->isBinary = 1;
     77     }
     78 
     79     /* global min priority defaults to "info" level */
     80     logState->globalMinPriority = ANDROID_LOG_INFO;
     81 
     82     /*
     83      * This is based on the utils/Log.cpp code.
     84      */
     85     const char* tags = getenv("ANDROID_LOG_TAGS");
     86     wsLog("Found ANDROID_LOG_TAGS='%s'\n", tags);
     87     if (tags != NULL) {
     88         int entry = 0;
     89 
     90         while (*tags != '\0') {
     91             char tagName[kMaxTagLen];
     92             int i, minPrio;
     93 
     94             while (isspace(*tags))
     95                 tags++;
     96 
     97             i = 0;
     98             while (*tags != '\0' && !isspace(*tags) && *tags != ':' &&
     99                 i < kMaxTagLen)
    100             {
    101                 tagName[i++] = *tags++;
    102             }
    103             if (i == kMaxTagLen) {
    104                 wsLog("ERROR: env tag too long (%d chars max)\n", kMaxTagLen-1);
    105                 return;
    106             }
    107             tagName[i] = '\0';
    108 
    109             /* default priority, if there's no ":" part; also zero out '*' */
    110             minPrio = ANDROID_LOG_VERBOSE;
    111             if (tagName[0] == '*' && tagName[1] == '\0') {
    112                 minPrio = ANDROID_LOG_DEBUG;
    113                 tagName[0] = '\0';
    114             }
    115 
    116             if (*tags == ':') {
    117                 tags++;
    118                 if (*tags >= '0' && *tags <= '9') {
    119                     if (*tags >= ('0' + ANDROID_LOG_SILENT))
    120                         minPrio = ANDROID_LOG_VERBOSE;
    121                     else
    122                         minPrio = *tags - '\0';
    123                 } else {
    124                     switch (*tags) {
    125                     case 'v':   minPrio = ANDROID_LOG_VERBOSE;  break;
    126                     case 'd':   minPrio = ANDROID_LOG_DEBUG;    break;
    127                     case 'i':   minPrio = ANDROID_LOG_INFO;     break;
    128                     case 'w':   minPrio = ANDROID_LOG_WARN;     break;
    129                     case 'e':   minPrio = ANDROID_LOG_ERROR;    break;
    130                     case 'f':   minPrio = ANDROID_LOG_FATAL;    break;
    131                     case 's':   minPrio = ANDROID_LOG_SILENT;   break;
    132                     default:    minPrio = ANDROID_LOG_DEFAULT;  break;
    133                     }
    134                 }
    135 
    136                 tags++;
    137                 if (*tags != '\0' && !isspace(*tags)) {
    138                     wsLog("ERROR: garbage in tag env; expected whitespace\n");
    139                     wsLog("       env='%s'\n", tags);
    140                     return;
    141                 }
    142             }
    143 
    144             if (tagName[0] == 0) {
    145                 logState->globalMinPriority = minPrio;
    146                 wsLog("+++ global min prio %d\n", logState->globalMinPriority);
    147             } else {
    148                 logState->tagSet[entry].minPriority = minPrio;
    149                 strcpy(logState->tagSet[entry].tag, tagName);
    150                 wsLog("+++ entry %d: %s:%d\n",
    151                     entry,
    152                     logState->tagSet[entry].tag,
    153                     logState->tagSet[entry].minPriority);
    154                 entry++;
    155             }
    156         }
    157     }
    158 
    159 
    160     /*
    161      * Taken from utils/Log.cpp
    162      */
    163     const char* fstr = getenv("ANDROID_PRINTF_LOG");
    164     LogFormat format;
    165     if (fstr == NULL) {
    166         format = FORMAT_BRIEF;
    167     } else {
    168         if (strcmp(fstr, "brief") == 0)
    169             format = FORMAT_BRIEF;
    170         else if (strcmp(fstr, "process") == 0)
    171             format = FORMAT_PROCESS;
    172         else if (strcmp(fstr, "tag") == 0)
    173             format = FORMAT_PROCESS;
    174         else if (strcmp(fstr, "thread") == 0)
    175             format = FORMAT_PROCESS;
    176         else if (strcmp(fstr, "raw") == 0)
    177             format = FORMAT_PROCESS;
    178         else if (strcmp(fstr, "time") == 0)
    179             format = FORMAT_PROCESS;
    180         else if (strcmp(fstr, "long") == 0)
    181             format = FORMAT_PROCESS;
    182         else
    183             format = (LogFormat) atoi(fstr);        // really?!
    184     }
    185 
    186     logState->outputFormat = format;
    187 }
    188 
    189 /*
    190  * Free up the state structure.
    191  */
    192 static void freeState(LogState* logState)
    193 {
    194     free(logState);
    195 }
    196 
    197 /*
    198  * Return a human-readable string for the priority level.  Always returns
    199  * a valid string.
    200  */
    201 static const char* getPriorityString(int priority)
    202 {
    203     /* the first character of each string should be unique */
    204     static const char* priorityStrings[] = {
    205         "Verbose", "Debug", "Info", "Warn", "Error", "Assert"
    206     };
    207     int idx;
    208 
    209     idx = (int) priority - (int) ANDROID_LOG_VERBOSE;
    210     if (idx < 0 ||
    211         idx >= (int) (sizeof(priorityStrings) / sizeof(priorityStrings[0])))
    212         return "?unknown?";
    213     return priorityStrings[idx];
    214 }
    215 
    216 /*
    217  * Show a log message.  We write it to stderr and send a copy to the
    218  * simulator front-end for the log window.
    219  *
    220  * Taken from utils/Log.cpp.
    221  */
    222 static void showLog(FakeDev* dev, int logPrio, const char* tag, const char* msg)
    223 {
    224     LogState* state = (LogState*) dev->state;
    225 
    226 #if defined(HAVE_LOCALTIME_R)
    227     struct tm tmBuf;
    228 #endif
    229     struct tm* ptm;
    230     char timeBuf[32];
    231     char prefixBuf[128], suffixBuf[128];
    232     char priChar;
    233     time_t when;
    234     pid_t pid, tid;
    235 
    236     //wsLog("LOG %d: %s %s", logPrio, tag, msg);
    237     wsPostLogMessage(logPrio, tag, msg);
    238 
    239     priChar = getPriorityString(logPrio)[0];
    240     when = time(NULL);
    241     pid = tid = getpid();       // find gettid()?
    242 
    243     /*
    244      * Get the current date/time in pretty form
    245      *
    246      * It's often useful when examining a log with "less" to jump to
    247      * a specific point in the file by searching for the date/time stamp.
    248      * For this reason it's very annoying to have regexp meta characters
    249      * in the time stamp.  Don't use forward slashes, parenthesis,
    250      * brackets, asterisks, or other special chars here.
    251      */
    252 #if defined(HAVE_LOCALTIME_R)
    253     ptm = localtime_r(&when, &tmBuf);
    254 #else
    255     ptm = localtime(&when);
    256 #endif
    257     //strftime(timeBuf, sizeof(timeBuf), "%Y-%m-%d %H:%M:%S", ptm);
    258     strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);
    259 
    260     /*
    261      * Construct a buffer containing the log header and log message.
    262      */
    263     size_t prefixLen, suffixLen;
    264 
    265     switch (state->outputFormat) {
    266     case FORMAT_TAG:
    267         prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
    268             "%c/%-8s: ", priChar, tag);
    269         strcpy(suffixBuf, "\n"); suffixLen = 1;
    270         break;
    271     case FORMAT_PROCESS:
    272         prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
    273             "%c(%5d) ", priChar, pid);
    274         suffixLen = snprintf(suffixBuf, sizeof(suffixBuf),
    275             "  (%s)\n", tag);
    276         break;
    277     case FORMAT_THREAD:
    278         prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
    279             "%c(%5d:%p) ", priChar, pid, (void*)tid);
    280         strcpy(suffixBuf, "\n"); suffixLen = 1;
    281         break;
    282     case FORMAT_RAW:
    283         prefixBuf[0] = 0; prefixLen = 0;
    284         strcpy(suffixBuf, "\n"); suffixLen = 1;
    285         break;
    286     case FORMAT_TIME:
    287         prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
    288             "%s %-8s\n\t", timeBuf, tag);
    289         strcpy(suffixBuf, "\n"); suffixLen = 1;
    290         break;
    291     case FORMAT_LONG:
    292         prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
    293             "[ %s %5d:%p %c/%-8s ]\n",
    294             timeBuf, pid, (void*)tid, priChar, tag);
    295         strcpy(suffixBuf, "\n\n"); suffixLen = 2;
    296         break;
    297     default:
    298         prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
    299             "%c/%-8s(%5d): ", priChar, tag, pid);
    300         strcpy(suffixBuf, "\n"); suffixLen = 1;
    301         break;
    302      }
    303 
    304     /*
    305      * Figure out how many lines there will be.
    306      */
    307     const char* end = msg + strlen(msg);
    308     size_t numLines = 0;
    309     const char* p = msg;
    310     while (p < end) {
    311         if (*p++ == '\n') numLines++;
    312     }
    313     if (p > msg && *(p-1) != '\n') numLines++;
    314 
    315     /*
    316      * Create an array of iovecs large enough to write all of
    317      * the lines with a prefix and a suffix.
    318      */
    319     const size_t INLINE_VECS = 6;
    320     struct iovec stackVec[INLINE_VECS];
    321     struct iovec* vec = stackVec;
    322 
    323     numLines *= 3;  // 3 iovecs per line.
    324     if (numLines > INLINE_VECS) {
    325         vec = (struct iovec*)malloc(sizeof(struct iovec)*numLines);
    326         if (vec == NULL) {
    327             msg = "LOG: write failed, no memory";
    328             numLines = 3;
    329         }
    330     }
    331 
    332     /*
    333      * Fill in the iovec pointers.
    334      */
    335     p = msg;
    336     struct iovec* v = vec;
    337     int totalLen = 0;
    338     while (p < end) {
    339         if (prefixLen > 0) {
    340             v->iov_base = prefixBuf;
    341             v->iov_len = prefixLen;
    342             totalLen += prefixLen;
    343             v++;
    344         }
    345         const char* start = p;
    346         while (p < end && *p != '\n') p++;
    347         if ((p-start) > 0) {
    348             v->iov_base = (void*)start;
    349             v->iov_len = p-start;
    350             totalLen += p-start;
    351             v++;
    352         }
    353         if (*p == '\n') p++;
    354         if (suffixLen > 0) {
    355             v->iov_base = suffixBuf;
    356             v->iov_len = suffixLen;
    357             totalLen += suffixLen;
    358             v++;
    359         }
    360     }
    361 
    362     /*
    363      * Write the entire message to the log file with a single writev() call.
    364      * We need to use this rather than a collection of printf()s on a FILE*
    365      * because of multi-threading and multi-process issues.
    366      *
    367      * If the file was not opened with O_APPEND, this will produce interleaved
    368      * output when called on the same file from multiple processes.
    369      *
    370      * If the file descriptor is actually a network socket, the writev()
    371      * call may return with a partial write.  Putting the writev() call in
    372      * a loop can result in interleaved data.  This can be alleviated
    373      * somewhat by wrapping the writev call in the Mutex.
    374      */
    375 
    376     for(;;) {
    377         int cc;
    378 
    379         cc = writev(fileno(stderr), vec, v-vec);
    380         if (cc == totalLen) break;
    381 
    382         if (cc < 0) {
    383             if(errno == EINTR) continue;
    384 
    385                 /* can't really log the failure; for now, throw out a stderr */
    386             fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
    387             break;
    388         } else {
    389                 /* shouldn't happen when writing to file or tty */
    390             fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", cc, totalLen);
    391             break;
    392         }
    393     }
    394 
    395     /* if we allocated storage for the iovecs, free it */
    396     if (vec != stackVec)
    397         free(vec);
    398 }
    399 
    400 
    401 /*
    402  * Receive a log message.  We happen to know that "vector" has three parts:
    403  *
    404  *  priority (1 byte)
    405  *  tag (N bytes -- null-terminated ASCII string)
    406  *  message (N bytes -- null-terminated ASCII string)
    407  */
    408 static ssize_t writevLog(FakeDev* dev, int fd, const struct iovec* vector,
    409     int count)
    410 {
    411     LogState* state = (LogState*) dev->state;
    412     int ret = 0;
    413 
    414     if (state->isBinary) {
    415         wsLog("%s: ignoring binary log\n", dev->debugName);
    416         goto bail;
    417     }
    418 
    419     if (count != 3) {
    420         wsLog("%s: writevLog with count=%d not expected\n",
    421             dev->debugName, count);
    422         errno = EINVAL;
    423         return -1;
    424     }
    425 
    426     /* pull out the three fields */
    427     int logPrio = *(const char*)vector[0].iov_base;
    428     const char* tag = (const char*) vector[1].iov_base;
    429     const char* msg = (const char*) vector[2].iov_base;
    430 
    431     /* see if this log tag is configured */
    432     int i;
    433     int minPrio = state->globalMinPriority;
    434     for (i = 0; i < kTagSetSize; i++) {
    435         if (state->tagSet[i].minPriority == ANDROID_LOG_UNKNOWN)
    436             break;      /* reached end of configured values */
    437 
    438         if (strcmp(state->tagSet[i].tag, tag) == 0) {
    439             //wsLog("MATCH tag '%s'\n", tag);
    440             minPrio = state->tagSet[i].minPriority;
    441             break;
    442         }
    443     }
    444 
    445     if (logPrio >= minPrio) {
    446         showLog(dev, logPrio, tag, msg);
    447     } else {
    448         //wsLog("+++ NOLOG(%d): %s %s", logPrio, tag, msg);
    449     }
    450 
    451 bail:
    452     for (i = 0; i < count; i++)
    453         ret += vector[i].iov_len;
    454     return ret;
    455 }
    456 
    457 /*
    458  * Free up our state before closing down the fake descriptor.
    459  */
    460 static int closeLog(FakeDev* dev, int fd)
    461 {
    462     freeState((LogState*)dev->state);
    463     dev->state = NULL;
    464     return 0;
    465 }
    466 
    467 /*
    468  * Open a log output device.
    469  */
    470 FakeDev* wsOpenDevLog(const char* pathName, int flags)
    471 {
    472     FakeDev* newDev = wsCreateFakeDev(pathName);
    473     if (newDev != NULL) {
    474         newDev->writev = writevLog;
    475         newDev->close = closeLog;
    476 
    477         LogState* logState = calloc(1, sizeof(LogState));
    478 
    479         configureInitialState(pathName, logState);
    480         newDev->state = logState;
    481     }
    482 
    483     return newDev;
    484 }
    485 
    486