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