1 /*
2 * Copyright 2007 The Android Open Source Project
3 *
4 * Log devices. We want to filter and display messages, with separate
5 * treatment for "debug" and "event" logs.
6 *
7 * All messages are just dumped to stderr.
8 */
9 #include "Common.h"
10
11 #include "cutils/logd.h"
12
13 #include <stdlib.h>
14 #include <string.h>
15 #include <ctype.h>
16
17 #include <fcntl.h>
18
19 #define kMaxTagLen 16 /* from utils/Log.cpp */
20
21 #define kTagSetSize 16 /* arbitrary */
22
23 /* from utils/Log.cpp */
24 typedef enum {
25 FORMAT_OFF = 0,
26 FORMAT_BRIEF,
27 FORMAT_PROCESS,
28 FORMAT_TAG,
29 FORMAT_THREAD,
30 FORMAT_RAW,
31 FORMAT_TIME,
32 FORMAT_LONG
33 } LogFormat;
34
35
36 /*
37 * Log driver state.
38 */
39 typedef struct LogState {
40 /* nonzero if this is a binary log */
41 int isBinary;
42
43 /* global minimum priority */
44 int globalMinPriority;
45
46 /* output format */
47 LogFormat outputFormat;
48
49 /* tags and priorities */
50 struct {
51 char tag[kMaxTagLen];
52 int minPriority;
53 } tagSet[kTagSetSize];
54 } LogState;
55
56
57 /*
58 * Configure logging based on ANDROID_LOG_TAGS environment variable. We
59 * need to parse a string that looks like
60 *
61 * '*:v jdwp:d dalvikvm:d dalvikvm-gc:i dalvikvmi:i
62 *
63 * The tag (or '*' for the global level) comes first, followed by a colon
64 * and a letter indicating the minimum priority level we're expected to log.
65 * This can be used to reveal or conceal logs with specific tags.
66 *
67 * We also want to check ANDROID_PRINTF_LOG to determine how the output
68 * will look.
69 */
configureInitialState(const char * pathName,LogState * logState)70 static void configureInitialState(const char* pathName, LogState* logState)
71 {
72 static const int kDevLogLen = 9; /* strlen("/dev/log/") */
73
74 /* identify binary logs */
75 if (strcmp(pathName + kDevLogLen, "events") == 0) {
76 logState->isBinary = 1;
77 }
78
79 /* global min priority defaults to "info" level */
80 logState->globalMinPriority = ANDROID_LOG_INFO;
81
82 /*
83 * This is based on the utils/Log.cpp code.
84 */
85 const char* tags = getenv("ANDROID_LOG_TAGS");
86 wsLog("Found ANDROID_LOG_TAGS='%s'\n", tags);
87 if (tags != NULL) {
88 int entry = 0;
89
90 while (*tags != '\0') {
91 char tagName[kMaxTagLen];
92 int i, minPrio;
93
94 while (isspace(*tags))
95 tags++;
96
97 i = 0;
98 while (*tags != '\0' && !isspace(*tags) && *tags != ':' &&
99 i < kMaxTagLen)
100 {
101 tagName[i++] = *tags++;
102 }
103 if (i == kMaxTagLen) {
104 wsLog("ERROR: env tag too long (%d chars max)\n", kMaxTagLen-1);
105 return;
106 }
107 tagName[i] = '\0';
108
109 /* default priority, if there's no ":" part; also zero out '*' */
110 minPrio = ANDROID_LOG_VERBOSE;
111 if (tagName[0] == '*' && tagName[1] == '\0') {
112 minPrio = ANDROID_LOG_DEBUG;
113 tagName[0] = '\0';
114 }
115
116 if (*tags == ':') {
117 tags++;
118 if (*tags >= '0' && *tags <= '9') {
119 if (*tags >= ('0' + ANDROID_LOG_SILENT))
120 minPrio = ANDROID_LOG_VERBOSE;
121 else
122 minPrio = *tags - '\0';
123 } else {
124 switch (*tags) {
125 case 'v': minPrio = ANDROID_LOG_VERBOSE; break;
126 case 'd': minPrio = ANDROID_LOG_DEBUG; break;
127 case 'i': minPrio = ANDROID_LOG_INFO; break;
128 case 'w': minPrio = ANDROID_LOG_WARN; break;
129 case 'e': minPrio = ANDROID_LOG_ERROR; break;
130 case 'f': minPrio = ANDROID_LOG_FATAL; break;
131 case 's': minPrio = ANDROID_LOG_SILENT; break;
132 default: minPrio = ANDROID_LOG_DEFAULT; break;
133 }
134 }
135
136 tags++;
137 if (*tags != '\0' && !isspace(*tags)) {
138 wsLog("ERROR: garbage in tag env; expected whitespace\n");
139 wsLog(" env='%s'\n", tags);
140 return;
141 }
142 }
143
144 if (tagName[0] == 0) {
145 logState->globalMinPriority = minPrio;
146 wsLog("+++ global min prio %d\n", logState->globalMinPriority);
147 } else {
148 logState->tagSet[entry].minPriority = minPrio;
149 strcpy(logState->tagSet[entry].tag, tagName);
150 wsLog("+++ entry %d: %s:%d\n",
151 entry,
152 logState->tagSet[entry].tag,
153 logState->tagSet[entry].minPriority);
154 entry++;
155 }
156 }
157 }
158
159
160 /*
161 * Taken from utils/Log.cpp
162 */
163 const char* fstr = getenv("ANDROID_PRINTF_LOG");
164 LogFormat format;
165 if (fstr == NULL) {
166 format = FORMAT_BRIEF;
167 } else {
168 if (strcmp(fstr, "brief") == 0)
169 format = FORMAT_BRIEF;
170 else if (strcmp(fstr, "process") == 0)
171 format = FORMAT_PROCESS;
172 else if (strcmp(fstr, "tag") == 0)
173 format = FORMAT_PROCESS;
174 else if (strcmp(fstr, "thread") == 0)
175 format = FORMAT_PROCESS;
176 else if (strcmp(fstr, "raw") == 0)
177 format = FORMAT_PROCESS;
178 else if (strcmp(fstr, "time") == 0)
179 format = FORMAT_PROCESS;
180 else if (strcmp(fstr, "long") == 0)
181 format = FORMAT_PROCESS;
182 else
183 format = (LogFormat) atoi(fstr); // really?!
184 }
185
186 logState->outputFormat = format;
187 }
188
189 /*
190 * Free up the state structure.
191 */
freeState(LogState * logState)192 static void freeState(LogState* logState)
193 {
194 free(logState);
195 }
196
197 /*
198 * Return a human-readable string for the priority level. Always returns
199 * a valid string.
200 */
getPriorityString(int priority)201 static const char* getPriorityString(int priority)
202 {
203 /* the first character of each string should be unique */
204 static const char* priorityStrings[] = {
205 "Verbose", "Debug", "Info", "Warn", "Error", "Assert"
206 };
207 int idx;
208
209 idx = (int) priority - (int) ANDROID_LOG_VERBOSE;
210 if (idx < 0 ||
211 idx >= (int) (sizeof(priorityStrings) / sizeof(priorityStrings[0])))
212 return "?unknown?";
213 return priorityStrings[idx];
214 }
215
216 /*
217 * Show a log message. We write it to stderr and send a copy to the
218 * simulator front-end for the log window.
219 *
220 * Taken from utils/Log.cpp.
221 */
showLog(FakeDev * dev,int logPrio,const char * tag,const char * msg)222 static void showLog(FakeDev* dev, int logPrio, const char* tag, const char* msg)
223 {
224 LogState* state = (LogState*) dev->state;
225
226 #if defined(HAVE_LOCALTIME_R)
227 struct tm tmBuf;
228 #endif
229 struct tm* ptm;
230 char timeBuf[32];
231 char prefixBuf[128], suffixBuf[128];
232 char priChar;
233 time_t when;
234 pid_t pid, tid;
235
236 //wsLog("LOG %d: %s %s", logPrio, tag, msg);
237 wsPostLogMessage(logPrio, tag, msg);
238
239 priChar = getPriorityString(logPrio)[0];
240 when = time(NULL);
241 pid = tid = getpid(); // find gettid()?
242
243 /*
244 * Get the current date/time in pretty form
245 *
246 * It's often useful when examining a log with "less" to jump to
247 * a specific point in the file by searching for the date/time stamp.
248 * For this reason it's very annoying to have regexp meta characters
249 * in the time stamp. Don't use forward slashes, parenthesis,
250 * brackets, asterisks, or other special chars here.
251 */
252 #if defined(HAVE_LOCALTIME_R)
253 ptm = localtime_r(&when, &tmBuf);
254 #else
255 ptm = localtime(&when);
256 #endif
257 //strftime(timeBuf, sizeof(timeBuf), "%Y-%m-%d %H:%M:%S", ptm);
258 strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);
259
260 /*
261 * Construct a buffer containing the log header and log message.
262 */
263 size_t prefixLen, suffixLen;
264
265 switch (state->outputFormat) {
266 case FORMAT_TAG:
267 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
268 "%c/%-8s: ", priChar, tag);
269 strcpy(suffixBuf, "\n"); suffixLen = 1;
270 break;
271 case FORMAT_PROCESS:
272 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
273 "%c(%5d) ", priChar, pid);
274 suffixLen = snprintf(suffixBuf, sizeof(suffixBuf),
275 " (%s)\n", tag);
276 break;
277 case FORMAT_THREAD:
278 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
279 "%c(%5d:%p) ", priChar, pid, (void*)tid);
280 strcpy(suffixBuf, "\n"); suffixLen = 1;
281 break;
282 case FORMAT_RAW:
283 prefixBuf[0] = 0; prefixLen = 0;
284 strcpy(suffixBuf, "\n"); suffixLen = 1;
285 break;
286 case FORMAT_TIME:
287 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
288 "%s %-8s\n\t", timeBuf, tag);
289 strcpy(suffixBuf, "\n"); suffixLen = 1;
290 break;
291 case FORMAT_LONG:
292 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
293 "[ %s %5d:%p %c/%-8s ]\n",
294 timeBuf, pid, (void*)tid, priChar, tag);
295 strcpy(suffixBuf, "\n\n"); suffixLen = 2;
296 break;
297 default:
298 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
299 "%c/%-8s(%5d): ", priChar, tag, pid);
300 strcpy(suffixBuf, "\n"); suffixLen = 1;
301 break;
302 }
303
304 /*
305 * Figure out how many lines there will be.
306 */
307 const char* end = msg + strlen(msg);
308 size_t numLines = 0;
309 const char* p = msg;
310 while (p < end) {
311 if (*p++ == '\n') numLines++;
312 }
313 if (p > msg && *(p-1) != '\n') numLines++;
314
315 /*
316 * Create an array of iovecs large enough to write all of
317 * the lines with a prefix and a suffix.
318 */
319 const size_t INLINE_VECS = 6;
320 struct iovec stackVec[INLINE_VECS];
321 struct iovec* vec = stackVec;
322
323 numLines *= 3; // 3 iovecs per line.
324 if (numLines > INLINE_VECS) {
325 vec = (struct iovec*)malloc(sizeof(struct iovec)*numLines);
326 if (vec == NULL) {
327 msg = "LOG: write failed, no memory";
328 numLines = 3;
329 }
330 }
331
332 /*
333 * Fill in the iovec pointers.
334 */
335 p = msg;
336 struct iovec* v = vec;
337 int totalLen = 0;
338 while (p < end) {
339 if (prefixLen > 0) {
340 v->iov_base = prefixBuf;
341 v->iov_len = prefixLen;
342 totalLen += prefixLen;
343 v++;
344 }
345 const char* start = p;
346 while (p < end && *p != '\n') p++;
347 if ((p-start) > 0) {
348 v->iov_base = (void*)start;
349 v->iov_len = p-start;
350 totalLen += p-start;
351 v++;
352 }
353 if (*p == '\n') p++;
354 if (suffixLen > 0) {
355 v->iov_base = suffixBuf;
356 v->iov_len = suffixLen;
357 totalLen += suffixLen;
358 v++;
359 }
360 }
361
362 /*
363 * Write the entire message to the log file with a single writev() call.
364 * We need to use this rather than a collection of printf()s on a FILE*
365 * because of multi-threading and multi-process issues.
366 *
367 * If the file was not opened with O_APPEND, this will produce interleaved
368 * output when called on the same file from multiple processes.
369 *
370 * If the file descriptor is actually a network socket, the writev()
371 * call may return with a partial write. Putting the writev() call in
372 * a loop can result in interleaved data. This can be alleviated
373 * somewhat by wrapping the writev call in the Mutex.
374 */
375
376 for(;;) {
377 int cc;
378
379 cc = writev(fileno(stderr), vec, v-vec);
380 if (cc == totalLen) break;
381
382 if (cc < 0) {
383 if(errno == EINTR) continue;
384
385 /* can't really log the failure; for now, throw out a stderr */
386 fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
387 break;
388 } else {
389 /* shouldn't happen when writing to file or tty */
390 fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", cc, totalLen);
391 break;
392 }
393 }
394
395 /* if we allocated storage for the iovecs, free it */
396 if (vec != stackVec)
397 free(vec);
398 }
399
400
401 /*
402 * Receive a log message. We happen to know that "vector" has three parts:
403 *
404 * priority (1 byte)
405 * tag (N bytes -- null-terminated ASCII string)
406 * message (N bytes -- null-terminated ASCII string)
407 */
writevLog(FakeDev * dev,int fd,const struct iovec * vector,int count)408 static ssize_t writevLog(FakeDev* dev, int fd, const struct iovec* vector,
409 int count)
410 {
411 LogState* state = (LogState*) dev->state;
412 int ret = 0;
413
414 if (state->isBinary) {
415 wsLog("%s: ignoring binary log\n", dev->debugName);
416 goto bail;
417 }
418
419 if (count != 3) {
420 wsLog("%s: writevLog with count=%d not expected\n",
421 dev->debugName, count);
422 errno = EINVAL;
423 return -1;
424 }
425
426 /* pull out the three fields */
427 int logPrio = *(const char*)vector[0].iov_base;
428 const char* tag = (const char*) vector[1].iov_base;
429 const char* msg = (const char*) vector[2].iov_base;
430
431 /* see if this log tag is configured */
432 int i;
433 int minPrio = state->globalMinPriority;
434 for (i = 0; i < kTagSetSize; i++) {
435 if (state->tagSet[i].minPriority == ANDROID_LOG_UNKNOWN)
436 break; /* reached end of configured values */
437
438 if (strcmp(state->tagSet[i].tag, tag) == 0) {
439 //wsLog("MATCH tag '%s'\n", tag);
440 minPrio = state->tagSet[i].minPriority;
441 break;
442 }
443 }
444
445 if (logPrio >= minPrio) {
446 showLog(dev, logPrio, tag, msg);
447 } else {
448 //wsLog("+++ NOLOG(%d): %s %s", logPrio, tag, msg);
449 }
450
451 bail:
452 for (i = 0; i < count; i++)
453 ret += vector[i].iov_len;
454 return ret;
455 }
456
457 /*
458 * Free up our state before closing down the fake descriptor.
459 */
closeLog(FakeDev * dev,int fd)460 static int closeLog(FakeDev* dev, int fd)
461 {
462 freeState((LogState*)dev->state);
463 dev->state = NULL;
464 return 0;
465 }
466
467 /*
468 * Open a log output device.
469 */
wsOpenDevLog(const char * pathName,int flags)470 FakeDev* wsOpenDevLog(const char* pathName, int flags)
471 {
472 FakeDev* newDev = wsCreateFakeDev(pathName);
473 if (newDev != NULL) {
474 newDev->writev = writevLog;
475 newDev->close = closeLog;
476
477 LogState* logState = calloc(1, sizeof(LogState));
478
479 configureInitialState(pathName, logState);
480 newDev->state = logState;
481 }
482
483 return newDev;
484 }
485
486