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