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