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 */
51typedef 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 */
67typedef 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 */
98static pthread_mutex_t fakeLogDeviceLock = PTHREAD_MUTEX_INITIALIZER;
99
100static void lock()
101{
102    pthread_mutex_lock(&fakeLogDeviceLock);
103}
104
105static 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
120static 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 */
126static 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 */
143static 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 */
154static 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 */
183static 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 */
308static 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 */
328static 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 */
352static 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 */
548static 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
600bail:
601    unlock();
602    return vector[0].iov_len + vector[1].iov_len + vector[2].iov_len;
603error:
604    unlock();
605    return -1;
606}
607
608/*
609 * Free up our state and close the fake descriptor.
610 */
611static 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 */
620static 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
647static int (*redirectOpen)(const char *pathName, int flags) = NULL;
648static int (*redirectClose)(int fd) = NULL;
649static ssize_t (*redirectWritev)(int fd, const struct iovec* vector, int count)
650        = NULL;
651
652static 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
673int fakeLogOpen(const char *pathName, int flags)
674{
675    if (redirectOpen == NULL) {
676        setRedirects();
677    }
678    return redirectOpen(pathName, flags);
679}
680
681int fakeLogClose(int fd)
682{
683    /* Assume that open() was called first. */
684    return redirectClose(fd);
685}
686
687ssize_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