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