fake_log_device.c revision d2c8f52189f8c2a13b88a107c6495f9d83196d2d 
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 */
45typedef 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 */
61typedef 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 */
92static pthread_mutex_t fakeLogDeviceLock = PTHREAD_MUTEX_INITIALIZER;
93
94static void lock()
95{
96    pthread_mutex_lock(&fakeLogDeviceLock);
97}
98
99static 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
114static 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 */
120static 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 */
137static 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 */
148static 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 */
177static 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 */
302static 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 */
322static 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 */
346static 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:%5d) ", priChar, pid, 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:%5d %c/%-8s ]\n",
421            timeBuf, pid, 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 */
542static 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
594bail:
595    unlock();
596    return vector[0].iov_len + vector[1].iov_len + vector[2].iov_len;
597error:
598    unlock();
599    return -1;
600}
601
602/*
603 * Free up our state and close the fake descriptor.
604 */
605static 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 */
614static 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
641static int (*redirectOpen)(const char *pathName, int flags) = NULL;
642static int (*redirectClose)(int fd) = NULL;
643static ssize_t (*redirectWritev)(int fd, const struct iovec* vector, int count)
644        = NULL;
645
646static 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
667int fakeLogOpen(const char *pathName, int flags)
668{
669    if (redirectOpen == NULL) {
670        setRedirects();
671    }
672    return redirectOpen(pathName, flags);
673}
674
675int fakeLogClose(int fd)
676{
677    /* Assume that open() was called first. */
678    return redirectClose(fd);
679}
680
681ssize_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}
686