/*
* Copyright (C) 2008 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
/*
* Intercepts log messages intended for the Android log device.
* When running in the context of the simulator, the messages are
* passed on to the underlying (fake) log device. When not in the
* simulator, messages are printed to stderr.
*/
#include <log/logd.h>
#include <stdlib.h>
#include <string.h>
#include <ctype.h>
#include <errno.h>
#include <fcntl.h>
#ifdef HAVE_PTHREADS
#include <pthread.h>
#endif
#define kMaxTagLen 16 /* from the long-dead utils/Log.cpp */
#define kTagSetSize 16 /* arbitrary */
#if 0
#define TRACE(...) printf("fake_log_device: " __VA_ARGS__)
#else
#define TRACE(...) ((void)0)
#endif
/* from the long-dead utils/Log.cpp */
typedef enum {
FORMAT_OFF = 0,
FORMAT_BRIEF,
FORMAT_PROCESS,
FORMAT_TAG,
FORMAT_THREAD,
FORMAT_RAW,
FORMAT_TIME,
FORMAT_THREADTIME,
FORMAT_LONG
} LogFormat;
/*
* Log driver state.
*/
typedef struct LogState {
/* the fake fd that's seen by the user */
int fakeFd;
/* a printable name for this fake device */
char *debugName;
/* nonzero if this is a binary log */
int isBinary;
/* global minimum priority */
int globalMinPriority;
/* output format */
LogFormat outputFormat;
/* tags and priorities */
struct {
char tag[kMaxTagLen];
int minPriority;
} tagSet[kTagSetSize];
} LogState;
#ifdef HAVE_PTHREADS
/*
* Locking. Since we're emulating a device, we need to be prepared
* to have multiple callers at the same time. This lock is used
* to both protect the fd list and to prevent LogStates from being
* freed out from under a user.
*/
static pthread_mutex_t fakeLogDeviceLock = PTHREAD_MUTEX_INITIALIZER;
static void lock()
{
pthread_mutex_lock(&fakeLogDeviceLock);
}
static void unlock()
{
pthread_mutex_unlock(&fakeLogDeviceLock);
}
#else // !HAVE_PTHREADS
#define lock() ((void)0)
#define unlock() ((void)0)
#endif // !HAVE_PTHREADS
/*
* File descriptor management.
*/
#define FAKE_FD_BASE 10000
#define MAX_OPEN_LOGS 16
static LogState *openLogTable[MAX_OPEN_LOGS];
/*
* Allocate an fd and associate a new LogState with it.
* The fd is available via the fakeFd field of the return value.
*/
static LogState *createLogState()
{
size_t i;
for (i = 0; i < sizeof(openLogTable); i++) {
if (openLogTable[i] == NULL) {
openLogTable[i] = calloc(1, sizeof(LogState));
openLogTable[i]->fakeFd = FAKE_FD_BASE + i;
return openLogTable[i];
}
}
return NULL;
}
/*
* Translate an fd to a LogState.
*/
static LogState *fdToLogState(int fd)
{
if (fd >= FAKE_FD_BASE && fd < FAKE_FD_BASE + MAX_OPEN_LOGS) {
return openLogTable[fd - FAKE_FD_BASE];
}
return NULL;
}
/*
* Unregister the fake fd and free the memory it pointed to.
*/
static void deleteFakeFd(int fd)
{
LogState *ls;
lock();
ls = fdToLogState(fd);
if (ls != NULL) {
openLogTable[fd - FAKE_FD_BASE] = NULL;
free(ls->debugName);
free(ls);
}
unlock();
}
/*
* Configure logging based on ANDROID_LOG_TAGS environment variable. We
* need to parse a string that looks like
*
* *:v jdwp:d dalvikvm:d dalvikvm-gc:i dalvikvmi:i
*
* The tag (or '*' for the global level) comes first, followed by a colon
* and a letter indicating the minimum priority level we're expected to log.
* This can be used to reveal or conceal logs with specific tags.
*
* We also want to check ANDROID_PRINTF_LOG to determine how the output
* will look.
*/
static void configureInitialState(const char* pathName, LogState* logState)
{
static const int kDevLogLen = sizeof("/dev/log/") - 1;
logState->debugName = strdup(pathName);
/* identify binary logs */
if (strcmp(pathName + kDevLogLen, "events") == 0) {
logState->isBinary = 1;
}
/* global min priority defaults to "info" level */
logState->globalMinPriority = ANDROID_LOG_INFO;
/*
* This is based on the the long-dead utils/Log.cpp code.
*/
const char* tags = getenv("ANDROID_LOG_TAGS");
TRACE("Found ANDROID_LOG_TAGS='%s'\n", tags);
if (tags != NULL) {
int entry = 0;
while (*tags != '\0') {
char tagName[kMaxTagLen];
int i, minPrio;
while (isspace(*tags))
tags++;
i = 0;
while (*tags != '\0' && !isspace(*tags) && *tags != ':' &&
i < kMaxTagLen)
{
tagName[i++] = *tags++;
}
if (i == kMaxTagLen) {
TRACE("ERROR: env tag too long (%d chars max)\n", kMaxTagLen-1);
return;
}
tagName[i] = '\0';
/* default priority, if there's no ":" part; also zero out '*' */
minPrio = ANDROID_LOG_VERBOSE;
if (tagName[0] == '*' && tagName[1] == '\0') {
minPrio = ANDROID_LOG_DEBUG;
tagName[0] = '\0';
}
if (*tags == ':') {
tags++;
if (*tags >= '0' && *tags <= '9') {
if (*tags >= ('0' + ANDROID_LOG_SILENT))
minPrio = ANDROID_LOG_VERBOSE;
else
minPrio = *tags - '\0';
} else {
switch (*tags) {
case 'v': minPrio = ANDROID_LOG_VERBOSE; break;
case 'd': minPrio = ANDROID_LOG_DEBUG; break;
case 'i': minPrio = ANDROID_LOG_INFO; break;
case 'w': minPrio = ANDROID_LOG_WARN; break;
case 'e': minPrio = ANDROID_LOG_ERROR; break;
case 'f': minPrio = ANDROID_LOG_FATAL; break;
case 's': minPrio = ANDROID_LOG_SILENT; break;
default: minPrio = ANDROID_LOG_DEFAULT; break;
}
}
tags++;
if (*tags != '\0' && !isspace(*tags)) {
TRACE("ERROR: garbage in tag env; expected whitespace\n");
TRACE(" env='%s'\n", tags);
return;
}
}
if (tagName[0] == 0) {
logState->globalMinPriority = minPrio;
TRACE("+++ global min prio %d\n", logState->globalMinPriority);
} else {
logState->tagSet[entry].minPriority = minPrio;
strcpy(logState->tagSet[entry].tag, tagName);
TRACE("+++ entry %d: %s:%d\n",
entry,
logState->tagSet[entry].tag,
logState->tagSet[entry].minPriority);
entry++;
}
}
}
/*
* Taken from the long-dead utils/Log.cpp
*/
const char* fstr = getenv("ANDROID_PRINTF_LOG");
LogFormat format;
if (fstr == NULL) {
format = FORMAT_BRIEF;
} else {
if (strcmp(fstr, "brief") == 0)
format = FORMAT_BRIEF;
else if (strcmp(fstr, "process") == 0)
format = FORMAT_PROCESS;
else if (strcmp(fstr, "tag") == 0)
format = FORMAT_PROCESS;
else if (strcmp(fstr, "thread") == 0)
format = FORMAT_PROCESS;
else if (strcmp(fstr, "raw") == 0)
format = FORMAT_PROCESS;
else if (strcmp(fstr, "time") == 0)
format = FORMAT_PROCESS;
else if (strcmp(fstr, "long") == 0)
format = FORMAT_PROCESS;
else
format = (LogFormat) atoi(fstr); // really?!
}
logState->outputFormat = format;
}
/*
* Return a human-readable string for the priority level. Always returns
* a valid string.
*/
static const char* getPriorityString(int priority)
{
/* the first character of each string should be unique */
static const char* priorityStrings[] = {
"Verbose", "Debug", "Info", "Warn", "Error", "Assert"
};
int idx;
idx = (int) priority - (int) ANDROID_LOG_VERBOSE;
if (idx < 0 ||
idx >= (int) (sizeof(priorityStrings) / sizeof(priorityStrings[0])))
return "?unknown?";
return priorityStrings[idx];
}
#ifndef HAVE_WRITEV
/*
* Some platforms like WIN32 do not have writev().
* Make up something to replace it.
*/
static ssize_t fake_writev(int fd, const struct iovec *iov, int iovcnt) {
int result = 0;
struct iovec* end = iov + iovcnt;
for (; iov < end; iov++) {
int w = write(fd, iov->iov_base, iov->iov_len);
if (w != iov->iov_len) {
if (w < 0)
return w;
return result + w;
}
result += w;
}
return result;
}
#define writev fake_writev
#endif
/*
* Write a filtered log message to stderr.
*
* Log format parsing taken from the long-dead utils/Log.cpp.
*/
static void showLog(LogState *state,
int logPrio, const char* tag, const char* msg)
{
#if defined(HAVE_LOCALTIME_R)
struct tm tmBuf;
#endif
struct tm* ptm;
char timeBuf[32];
char prefixBuf[128], suffixBuf[128];
char priChar;
time_t when;
pid_t pid, tid;
TRACE("LOG %d: %s %s", logPrio, tag, msg);
priChar = getPriorityString(logPrio)[0];
when = time(NULL);
pid = tid = getpid(); // find gettid()?
/*
* Get the current date/time in pretty form
*
* It's often useful when examining a log with "less" to jump to
* a specific point in the file by searching for the date/time stamp.
* For this reason it's very annoying to have regexp meta characters
* in the time stamp. Don't use forward slashes, parenthesis,
* brackets, asterisks, or other special chars here.
*/
#if defined(HAVE_LOCALTIME_R)
ptm = localtime_r(&when, &tmBuf);
#else
ptm = localtime(&when);
#endif
//strftime(timeBuf, sizeof(timeBuf), "%Y-%m-%d %H:%M:%S", ptm);
strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);
/*
* Construct a buffer containing the log header and log message.
*/
size_t prefixLen, suffixLen;
switch (state->outputFormat) {
case FORMAT_TAG:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"%c/%-8s: ", priChar, tag);
strcpy(suffixBuf, "\n"); suffixLen = 1;
break;
case FORMAT_PROCESS:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"%c(%5d) ", priChar, pid);
suffixLen = snprintf(suffixBuf, sizeof(suffixBuf),
" (%s)\n", tag);
break;
case FORMAT_THREAD:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"%c(%5d:%5d) ", priChar, pid, tid);
strcpy(suffixBuf, "\n"); suffixLen = 1;
break;
case FORMAT_RAW:
prefixBuf[0] = 0; prefixLen = 0;
strcpy(suffixBuf, "\n"); suffixLen = 1;
break;
case FORMAT_TIME:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"%s %-8s\n\t", timeBuf, tag);
strcpy(suffixBuf, "\n"); suffixLen = 1;
break;
case FORMAT_THREADTIME:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"%s %5d %5d %c %-8s \n\t", timeBuf, pid, tid, priChar, tag);
strcpy(suffixBuf, "\n"); suffixLen = 1;
break;
case FORMAT_LONG:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"[ %s %5d:%5d %c/%-8s ]\n",
timeBuf, pid, tid, priChar, tag);
strcpy(suffixBuf, "\n\n"); suffixLen = 2;
break;
default:
prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
"%c/%-8s(%5d): ", priChar, tag, pid);
strcpy(suffixBuf, "\n"); suffixLen = 1;
break;
}
/*
* Figure out how many lines there will be.
*/
const char* end = msg + strlen(msg);
size_t numLines = 0;
const char* p = msg;
while (p < end) {
if (*p++ == '\n') numLines++;
}
if (p > msg && *(p-1) != '\n') numLines++;
/*
* Create an array of iovecs large enough to write all of
* the lines with a prefix and a suffix.
*/
const size_t INLINE_VECS = 6;
const size_t MAX_LINES = ((size_t)~0)/(3*sizeof(struct iovec*));
struct iovec stackVec[INLINE_VECS];
struct iovec* vec = stackVec;
size_t numVecs;
if (numLines > MAX_LINES)
numLines = MAX_LINES;
numVecs = numLines*3; // 3 iovecs per line.
if (numVecs > INLINE_VECS) {
vec = (struct iovec*)malloc(sizeof(struct iovec)*numVecs);
if (vec == NULL) {
msg = "LOG: write failed, no memory";
numVecs = 3;
numLines = 1;
vec = stackVec;
}
}
/*
* Fill in the iovec pointers.
*/
p = msg;
struct iovec* v = vec;
int totalLen = 0;
while (numLines > 0 && p < end) {
if (prefixLen > 0) {
v->iov_base = prefixBuf;
v->iov_len = prefixLen;
totalLen += prefixLen;
v++;
}
const char* start = p;
while (p < end && *p != '\n') p++;
if ((p-start) > 0) {
v->iov_base = (void*)start;
v->iov_len = p-start;
totalLen += p-start;
v++;
}
if (*p == '\n') p++;
if (suffixLen > 0) {
v->iov_base = suffixBuf;
v->iov_len = suffixLen;
totalLen += suffixLen;
v++;
}
numLines -= 1;
}
/*
* Write the entire message to the log file with a single writev() call.
* We need to use this rather than a collection of printf()s on a FILE*
* because of multi-threading and multi-process issues.
*
* If the file was not opened with O_APPEND, this will produce interleaved
* output when called on the same file from multiple processes.
*
* If the file descriptor is actually a network socket, the writev()
* call may return with a partial write. Putting the writev() call in
* a loop can result in interleaved data. This can be alleviated
* somewhat by wrapping the writev call in the Mutex.
*/
for(;;) {
int cc = writev(fileno(stderr), vec, v-vec);
if (cc == totalLen) break;
if (cc < 0) {
if(errno == EINTR) continue;
/* can't really log the failure; for now, throw out a stderr */
fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
break;
} else {
/* shouldn't happen when writing to file or tty */
fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", cc, totalLen);
break;
}
}
/* if we allocated storage for the iovecs, free it */
if (vec != stackVec)
free(vec);
}
/*
* Receive a log message. We happen to know that "vector" has three parts:
*
* priority (1 byte)
* tag (N bytes -- null-terminated ASCII string)
* message (N bytes -- null-terminated ASCII string)
*/
static ssize_t logWritev(int fd, const struct iovec* vector, int count)
{
LogState* state;
/* Make sure that no-one frees the LogState while we're using it.
* Also guarantees that only one thread is in showLog() at a given
* time (if it matters).
*/
lock();
state = fdToLogState(fd);
if (state == NULL) {
errno = EBADF;
goto error;
}
if (state->isBinary) {
TRACE("%s: ignoring binary log\n", state->debugName);
goto bail;
}
if (count != 3) {
TRACE("%s: writevLog with count=%d not expected\n",
state->debugName, count);
goto error;
}
/* pull out the three fields */
int logPrio = *(const char*)vector[0].iov_base;
const char* tag = (const char*) vector[1].iov_base;
const char* msg = (const char*) vector[2].iov_base;
/* see if this log tag is configured */
int i;
int minPrio = state->globalMinPriority;
for (i = 0; i < kTagSetSize; i++) {
if (state->tagSet[i].minPriority == ANDROID_LOG_UNKNOWN)
break; /* reached end of configured values */
if (strcmp(state->tagSet[i].tag, tag) == 0) {
//TRACE("MATCH tag '%s'\n", tag);
minPrio = state->tagSet[i].minPriority;
break;
}
}
if (logPrio >= minPrio) {
showLog(state, logPrio, tag, msg);
} else {
//TRACE("+++ NOLOG(%d): %s %s", logPrio, tag, msg);
}
bail:
unlock();
return vector[0].iov_len + vector[1].iov_len + vector[2].iov_len;
error:
unlock();
return -1;
}
/*
* Free up our state and close the fake descriptor.
*/
static int logClose(int fd)
{
deleteFakeFd(fd);
return 0;
}
/*
* Open a log output device and return a fake fd.
*/
static int logOpen(const char* pathName, int flags)
{
LogState *logState;
int fd = -1;
lock();
logState = createLogState();
if (logState != NULL) {
configureInitialState(pathName, logState);
fd = logState->fakeFd;
} else {
errno = ENFILE;
}
unlock();
return fd;
}
/*
* Runtime redirection. If this binary is running in the simulator,
* just pass log messages to the emulated device. If it's running
* outside of the simulator, write the log messages to stderr.
*/
static int (*redirectOpen)(const char *pathName, int flags) = NULL;
static int (*redirectClose)(int fd) = NULL;
static ssize_t (*redirectWritev)(int fd, const struct iovec* vector, int count)
= NULL;
static void setRedirects()
{
const char *ws;
/* Wrapsim sets this environment variable on children that it's
* created using its LD_PRELOAD wrapper.
*/
ws = getenv("ANDROID_WRAPSIM");
if (ws != NULL && strcmp(ws, "1") == 0) {
/* We're running inside wrapsim, so we can just write to the device. */
redirectOpen = (int (*)(const char *pathName, int flags))open;
redirectClose = close;
redirectWritev = writev;
} else {
/* There's no device to delegate to; handle the logging ourselves. */
redirectOpen = logOpen;
redirectClose = logClose;
redirectWritev = logWritev;
}
}
int fakeLogOpen(const char *pathName, int flags)
{
if (redirectOpen == NULL) {
setRedirects();
}
return redirectOpen(pathName, flags);
}
int fakeLogClose(int fd)
{
/* Assume that open() was called first. */
return redirectClose(fd);
}
ssize_t fakeLogWritev(int fd, const struct iovec* vector, int count)
{
/* Assume that open() was called first. */
return redirectWritev(fd, vector, count);
}