1 /*
2 **
3 ** Copyright 2006-2014, The Android Open Source Project
4 **
5 ** Licensed under the Apache License, Version 2.0 (the "License");
6 ** you may not use this file except in compliance with the License.
7 ** You may obtain a copy of the License at
8 **
9 ** http://www.apache.org/licenses/LICENSE-2.0
10 **
11 ** Unless required by applicable law or agreed to in writing, software
12 ** distributed under the License is distributed on an "AS IS" BASIS,
13 ** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 ** See the License for the specific language governing permissions and
15 ** limitations under the License.
16 */
17
18 #define _GNU_SOURCE /* for asprintf */
19 #ifndef __MINGW32__
20 #define HAVE_STRSEP
21 #endif
22
23 #include <assert.h>
24 #include <ctype.h>
25 #include <errno.h>
26 #include <inttypes.h>
27 #ifndef __MINGW32__
28 #include <pwd.h>
29 #endif
30 #include <stdbool.h>
31 #include <stdint.h>
32 #include <stdio.h>
33 #include <stdlib.h>
34 #include <string.h>
35 #include <sys/param.h>
36 #include <sys/types.h>
37
38 #include <cutils/list.h>
39 #include <log/log.h>
40 #include <log/logprint.h>
41
42 #include "log_portability.h"
43
44 #define MS_PER_NSEC 1000000
45 #define US_PER_NSEC 1000
46
47 #ifndef MIN
48 #define MIN(a, b) (((a) < (b)) ? (a) : (b))
49 #endif
50
51 typedef struct FilterInfo_t {
52 char* mTag;
53 android_LogPriority mPri;
54 struct FilterInfo_t* p_next;
55 } FilterInfo;
56
57 struct AndroidLogFormat_t {
58 android_LogPriority global_pri;
59 FilterInfo* filters;
60 AndroidLogPrintFormat format;
61 bool colored_output;
62 bool usec_time_output;
63 bool nsec_time_output;
64 bool printable_output;
65 bool year_output;
66 bool zone_output;
67 bool epoch_output;
68 bool monotonic_output;
69 bool uid_output;
70 bool descriptive_output;
71 };
72
73 /*
74 * API issues prevent us from exposing "descriptive" in AndroidLogFormat_t
75 * during android_log_processBinaryLogBuffer(), so we break layering.
76 */
77 static bool descriptive_output = false;
78
79 /*
80 * gnome-terminal color tags
81 * See http://misc.flogisoft.com/bash/tip_colors_and_formatting
82 * for ideas on how to set the forground color of the text for xterm.
83 * The color manipulation character stream is defined as:
84 * ESC [ 3 8 ; 5 ; <color#> m
85 */
86 #define ANDROID_COLOR_BLUE 75
87 #define ANDROID_COLOR_DEFAULT 231
88 #define ANDROID_COLOR_GREEN 40
89 #define ANDROID_COLOR_ORANGE 166
90 #define ANDROID_COLOR_RED 196
91 #define ANDROID_COLOR_YELLOW 226
92
filterinfo_new(const char * tag,android_LogPriority pri)93 static FilterInfo* filterinfo_new(const char* tag, android_LogPriority pri) {
94 FilterInfo* p_ret;
95
96 p_ret = (FilterInfo*)calloc(1, sizeof(FilterInfo));
97 p_ret->mTag = strdup(tag);
98 p_ret->mPri = pri;
99
100 return p_ret;
101 }
102
103 /* balance to above, filterinfo_free left unimplemented */
104
105 /*
106 * Note: also accepts 0-9 priorities
107 * returns ANDROID_LOG_UNKNOWN if the character is unrecognized
108 */
filterCharToPri(char c)109 static android_LogPriority filterCharToPri(char c) {
110 android_LogPriority pri;
111
112 c = tolower(c);
113
114 if (c >= '0' && c <= '9') {
115 if (c >= ('0' + ANDROID_LOG_SILENT)) {
116 pri = ANDROID_LOG_VERBOSE;
117 } else {
118 pri = (android_LogPriority)(c - '0');
119 }
120 } else if (c == 'v') {
121 pri = ANDROID_LOG_VERBOSE;
122 } else if (c == 'd') {
123 pri = ANDROID_LOG_DEBUG;
124 } else if (c == 'i') {
125 pri = ANDROID_LOG_INFO;
126 } else if (c == 'w') {
127 pri = ANDROID_LOG_WARN;
128 } else if (c == 'e') {
129 pri = ANDROID_LOG_ERROR;
130 } else if (c == 'f') {
131 pri = ANDROID_LOG_FATAL;
132 } else if (c == 's') {
133 pri = ANDROID_LOG_SILENT;
134 } else if (c == '*') {
135 pri = ANDROID_LOG_DEFAULT;
136 } else {
137 pri = ANDROID_LOG_UNKNOWN;
138 }
139
140 return pri;
141 }
142
filterPriToChar(android_LogPriority pri)143 static char filterPriToChar(android_LogPriority pri) {
144 switch (pri) {
145 /* clang-format off */
146 case ANDROID_LOG_VERBOSE: return 'V';
147 case ANDROID_LOG_DEBUG: return 'D';
148 case ANDROID_LOG_INFO: return 'I';
149 case ANDROID_LOG_WARN: return 'W';
150 case ANDROID_LOG_ERROR: return 'E';
151 case ANDROID_LOG_FATAL: return 'F';
152 case ANDROID_LOG_SILENT: return 'S';
153
154 case ANDROID_LOG_DEFAULT:
155 case ANDROID_LOG_UNKNOWN:
156 default: return '?';
157 /* clang-format on */
158 }
159 }
160
colorFromPri(android_LogPriority pri)161 static int colorFromPri(android_LogPriority pri) {
162 switch (pri) {
163 /* clang-format off */
164 case ANDROID_LOG_VERBOSE: return ANDROID_COLOR_DEFAULT;
165 case ANDROID_LOG_DEBUG: return ANDROID_COLOR_BLUE;
166 case ANDROID_LOG_INFO: return ANDROID_COLOR_GREEN;
167 case ANDROID_LOG_WARN: return ANDROID_COLOR_ORANGE;
168 case ANDROID_LOG_ERROR: return ANDROID_COLOR_RED;
169 case ANDROID_LOG_FATAL: return ANDROID_COLOR_RED;
170 case ANDROID_LOG_SILENT: return ANDROID_COLOR_DEFAULT;
171
172 case ANDROID_LOG_DEFAULT:
173 case ANDROID_LOG_UNKNOWN:
174 default: return ANDROID_COLOR_DEFAULT;
175 /* clang-format on */
176 }
177 }
178
filterPriForTag(AndroidLogFormat * p_format,const char * tag)179 static android_LogPriority filterPriForTag(AndroidLogFormat* p_format,
180 const char* tag) {
181 FilterInfo* p_curFilter;
182
183 for (p_curFilter = p_format->filters; p_curFilter != NULL;
184 p_curFilter = p_curFilter->p_next) {
185 if (0 == strcmp(tag, p_curFilter->mTag)) {
186 if (p_curFilter->mPri == ANDROID_LOG_DEFAULT) {
187 return p_format->global_pri;
188 } else {
189 return p_curFilter->mPri;
190 }
191 }
192 }
193
194 return p_format->global_pri;
195 }
196
197 /**
198 * returns 1 if this log line should be printed based on its priority
199 * and tag, and 0 if it should not
200 */
android_log_shouldPrintLine(AndroidLogFormat * p_format,const char * tag,android_LogPriority pri)201 LIBLOG_ABI_PUBLIC int android_log_shouldPrintLine(AndroidLogFormat* p_format,
202 const char* tag,
203 android_LogPriority pri) {
204 return pri >= filterPriForTag(p_format, tag);
205 }
206
android_log_format_new()207 LIBLOG_ABI_PUBLIC AndroidLogFormat* android_log_format_new() {
208 AndroidLogFormat* p_ret;
209
210 p_ret = calloc(1, sizeof(AndroidLogFormat));
211
212 p_ret->global_pri = ANDROID_LOG_VERBOSE;
213 p_ret->format = FORMAT_BRIEF;
214 p_ret->colored_output = false;
215 p_ret->usec_time_output = false;
216 p_ret->nsec_time_output = false;
217 p_ret->printable_output = false;
218 p_ret->year_output = false;
219 p_ret->zone_output = false;
220 p_ret->epoch_output = false;
221 #ifdef __ANDROID__
222 p_ret->monotonic_output = android_log_clockid() == CLOCK_MONOTONIC;
223 #else
224 p_ret->monotonic_output = false;
225 #endif
226 p_ret->uid_output = false;
227 p_ret->descriptive_output = false;
228 descriptive_output = false;
229
230 return p_ret;
231 }
232
233 static list_declare(convertHead);
234
android_log_format_free(AndroidLogFormat * p_format)235 LIBLOG_ABI_PUBLIC void android_log_format_free(AndroidLogFormat* p_format) {
236 FilterInfo *p_info, *p_info_old;
237
238 p_info = p_format->filters;
239
240 while (p_info != NULL) {
241 p_info_old = p_info;
242 p_info = p_info->p_next;
243
244 free(p_info_old);
245 }
246
247 free(p_format);
248
249 /* Free conversion resource, can always be reconstructed */
250 while (!list_empty(&convertHead)) {
251 struct listnode* node = list_head(&convertHead);
252 list_remove(node);
253 free(node);
254 }
255 }
256
android_log_setPrintFormat(AndroidLogFormat * p_format,AndroidLogPrintFormat format)257 LIBLOG_ABI_PUBLIC int android_log_setPrintFormat(AndroidLogFormat* p_format,
258 AndroidLogPrintFormat format) {
259 switch (format) {
260 case FORMAT_MODIFIER_COLOR:
261 p_format->colored_output = true;
262 return 0;
263 case FORMAT_MODIFIER_TIME_USEC:
264 p_format->usec_time_output = true;
265 return 0;
266 case FORMAT_MODIFIER_TIME_NSEC:
267 p_format->nsec_time_output = true;
268 return 0;
269 case FORMAT_MODIFIER_PRINTABLE:
270 p_format->printable_output = true;
271 return 0;
272 case FORMAT_MODIFIER_YEAR:
273 p_format->year_output = true;
274 return 0;
275 case FORMAT_MODIFIER_ZONE:
276 p_format->zone_output = !p_format->zone_output;
277 return 0;
278 case FORMAT_MODIFIER_EPOCH:
279 p_format->epoch_output = true;
280 return 0;
281 case FORMAT_MODIFIER_MONOTONIC:
282 p_format->monotonic_output = true;
283 return 0;
284 case FORMAT_MODIFIER_UID:
285 p_format->uid_output = true;
286 return 0;
287 case FORMAT_MODIFIER_DESCRIPT:
288 p_format->descriptive_output = true;
289 descriptive_output = true;
290 return 0;
291 default:
292 break;
293 }
294 p_format->format = format;
295 return 1;
296 }
297
298 static const char tz[] = "TZ";
299 static const char utc[] = "UTC";
300
301 /**
302 * Returns FORMAT_OFF on invalid string
303 */
304 LIBLOG_ABI_PUBLIC AndroidLogPrintFormat
android_log_formatFromString(const char * formatString)305 android_log_formatFromString(const char* formatString) {
306 static AndroidLogPrintFormat format;
307
308 /* clang-format off */
309 if (!strcmp(formatString, "brief")) format = FORMAT_BRIEF;
310 else if (!strcmp(formatString, "process")) format = FORMAT_PROCESS;
311 else if (!strcmp(formatString, "tag")) format = FORMAT_TAG;
312 else if (!strcmp(formatString, "thread")) format = FORMAT_THREAD;
313 else if (!strcmp(formatString, "raw")) format = FORMAT_RAW;
314 else if (!strcmp(formatString, "time")) format = FORMAT_TIME;
315 else if (!strcmp(formatString, "threadtime")) format = FORMAT_THREADTIME;
316 else if (!strcmp(formatString, "long")) format = FORMAT_LONG;
317 else if (!strcmp(formatString, "color")) format = FORMAT_MODIFIER_COLOR;
318 else if (!strcmp(formatString, "colour")) format = FORMAT_MODIFIER_COLOR;
319 else if (!strcmp(formatString, "usec")) format = FORMAT_MODIFIER_TIME_USEC;
320 else if (!strcmp(formatString, "nsec")) format = FORMAT_MODIFIER_TIME_NSEC;
321 else if (!strcmp(formatString, "printable")) format = FORMAT_MODIFIER_PRINTABLE;
322 else if (!strcmp(formatString, "year")) format = FORMAT_MODIFIER_YEAR;
323 else if (!strcmp(formatString, "zone")) format = FORMAT_MODIFIER_ZONE;
324 else if (!strcmp(formatString, "epoch")) format = FORMAT_MODIFIER_EPOCH;
325 else if (!strcmp(formatString, "monotonic")) format = FORMAT_MODIFIER_MONOTONIC;
326 else if (!strcmp(formatString, "uid")) format = FORMAT_MODIFIER_UID;
327 else if (!strcmp(formatString, "descriptive")) format = FORMAT_MODIFIER_DESCRIPT;
328 /* clang-format on */
329
330 #ifndef __MINGW32__
331 else {
332 extern char* tzname[2];
333 static const char gmt[] = "GMT";
334 char* cp = getenv(tz);
335 if (cp) {
336 cp = strdup(cp);
337 }
338 setenv(tz, formatString, 1);
339 /*
340 * Run tzset here to determine if the timezone is legitimate. If the
341 * zone is GMT, check if that is what was asked for, if not then
342 * did not match any on the system; report an error to caller.
343 */
344 tzset();
345 if (!tzname[0] ||
346 ((!strcmp(tzname[0], utc) || !strcmp(tzname[0], gmt)) /* error? */
347 && strcasecmp(formatString, utc) &&
348 strcasecmp(formatString, gmt))) { /* ok */
349 if (cp) {
350 setenv(tz, cp, 1);
351 } else {
352 unsetenv(tz);
353 }
354 tzset();
355 format = FORMAT_OFF;
356 } else {
357 format = FORMAT_MODIFIER_ZONE;
358 }
359 free(cp);
360 }
361 #endif
362
363 return format;
364 }
365
366 /**
367 * filterExpression: a single filter expression
368 * eg "AT:d"
369 *
370 * returns 0 on success and -1 on invalid expression
371 *
372 * Assumes single threaded execution
373 */
374
android_log_addFilterRule(AndroidLogFormat * p_format,const char * filterExpression)375 LIBLOG_ABI_PUBLIC int android_log_addFilterRule(AndroidLogFormat* p_format,
376 const char* filterExpression) {
377 size_t tagNameLength;
378 android_LogPriority pri = ANDROID_LOG_DEFAULT;
379
380 tagNameLength = strcspn(filterExpression, ":");
381
382 if (tagNameLength == 0) {
383 goto error;
384 }
385
386 if (filterExpression[tagNameLength] == ':') {
387 pri = filterCharToPri(filterExpression[tagNameLength + 1]);
388
389 if (pri == ANDROID_LOG_UNKNOWN) {
390 goto error;
391 }
392 }
393
394 if (0 == strncmp("*", filterExpression, tagNameLength)) {
395 /*
396 * This filter expression refers to the global filter
397 * The default level for this is DEBUG if the priority
398 * is unspecified
399 */
400 if (pri == ANDROID_LOG_DEFAULT) {
401 pri = ANDROID_LOG_DEBUG;
402 }
403
404 p_format->global_pri = pri;
405 } else {
406 /*
407 * for filter expressions that don't refer to the global
408 * filter, the default is verbose if the priority is unspecified
409 */
410 if (pri == ANDROID_LOG_DEFAULT) {
411 pri = ANDROID_LOG_VERBOSE;
412 }
413
414 char* tagName;
415
416 /*
417 * Presently HAVE_STRNDUP is never defined, so the second case is always taken
418 * Darwin doesn't have strndup, everything else does
419 */
420 #ifdef HAVE_STRNDUP
421 tagName = strndup(filterExpression, tagNameLength);
422 #else
423 /* a few extra bytes copied... */
424 tagName = strdup(filterExpression);
425 tagName[tagNameLength] = '\0';
426 #endif /*HAVE_STRNDUP*/
427
428 FilterInfo* p_fi = filterinfo_new(tagName, pri);
429 free(tagName);
430
431 p_fi->p_next = p_format->filters;
432 p_format->filters = p_fi;
433 }
434
435 return 0;
436 error:
437 return -1;
438 }
439
440 #ifndef HAVE_STRSEP
441 /* KISS replacement helper for below */
strsep(char ** stringp,const char * delim)442 static char* strsep(char** stringp, const char* delim) {
443 char* token;
444 char* ret = *stringp;
445
446 if (!ret || !*ret) {
447 return NULL;
448 }
449 token = strpbrk(ret, delim);
450 if (token) {
451 *token = '\0';
452 ++token;
453 } else {
454 token = ret + strlen(ret);
455 }
456 *stringp = token;
457 return ret;
458 }
459 #endif
460
461 /**
462 * filterString: a comma/whitespace-separated set of filter expressions
463 *
464 * eg "AT:d *:i"
465 *
466 * returns 0 on success and -1 on invalid expression
467 *
468 * Assumes single threaded execution
469 *
470 */
android_log_addFilterString(AndroidLogFormat * p_format,const char * filterString)471 LIBLOG_ABI_PUBLIC int android_log_addFilterString(AndroidLogFormat* p_format,
472 const char* filterString) {
473 char* filterStringCopy = strdup(filterString);
474 char* p_cur = filterStringCopy;
475 char* p_ret;
476 int err;
477
478 /* Yes, I'm using strsep */
479 while (NULL != (p_ret = strsep(&p_cur, " \t,"))) {
480 /* ignore whitespace-only entries */
481 if (p_ret[0] != '\0') {
482 err = android_log_addFilterRule(p_format, p_ret);
483
484 if (err < 0) {
485 goto error;
486 }
487 }
488 }
489
490 free(filterStringCopy);
491 return 0;
492 error:
493 free(filterStringCopy);
494 return -1;
495 }
496
497 /**
498 * Splits a wire-format buffer into an AndroidLogEntry
499 * entry allocated by caller. Pointers will point directly into buf
500 *
501 * Returns 0 on success and -1 on invalid wire format (entry will be
502 * in unspecified state)
503 */
android_log_processLogBuffer(struct logger_entry * buf,AndroidLogEntry * entry)504 LIBLOG_ABI_PUBLIC int android_log_processLogBuffer(struct logger_entry* buf,
505 AndroidLogEntry* entry) {
506 entry->message = NULL;
507 entry->messageLen = 0;
508
509 entry->tv_sec = buf->sec;
510 entry->tv_nsec = buf->nsec;
511 entry->uid = -1;
512 entry->pid = buf->pid;
513 entry->tid = buf->tid;
514
515 /*
516 * format: <priority:1><tag:N>\0<message:N>\0
517 *
518 * tag str
519 * starts at buf->msg+1
520 * msg
521 * starts at buf->msg+1+len(tag)+1
522 *
523 * The message may have been truncated by the kernel log driver.
524 * When that happens, we must null-terminate the message ourselves.
525 */
526 if (buf->len < 3) {
527 /*
528 * An well-formed entry must consist of at least a priority
529 * and two null characters
530 */
531 fprintf(stderr, "+++ LOG: entry too small\n");
532 return -1;
533 }
534
535 int msgStart = -1;
536 int msgEnd = -1;
537
538 int i;
539 char* msg = buf->msg;
540 struct logger_entry_v2* buf2 = (struct logger_entry_v2*)buf;
541 if (buf2->hdr_size) {
542 if ((buf2->hdr_size < sizeof(((struct log_msg*)NULL)->entry_v1)) ||
543 (buf2->hdr_size > sizeof(((struct log_msg*)NULL)->entry))) {
544 fprintf(stderr, "+++ LOG: entry illegal hdr_size\n");
545 return -1;
546 }
547 msg = ((char*)buf2) + buf2->hdr_size;
548 if (buf2->hdr_size >= sizeof(struct logger_entry_v4)) {
549 entry->uid = ((struct logger_entry_v4*)buf)->uid;
550 }
551 }
552 for (i = 1; i < buf->len; i++) {
553 if (msg[i] == '\0') {
554 if (msgStart == -1) {
555 msgStart = i + 1;
556 } else {
557 msgEnd = i;
558 break;
559 }
560 }
561 }
562
563 if (msgStart == -1) {
564 /* +++ LOG: malformed log message, DYB */
565 for (i = 1; i < buf->len; i++) {
566 /* odd characters in tag? */
567 if ((msg[i] <= ' ') || (msg[i] == ':') || (msg[i] >= 0x7f)) {
568 msg[i] = '\0';
569 msgStart = i + 1;
570 break;
571 }
572 }
573 if (msgStart == -1) {
574 msgStart = buf->len - 1; /* All tag, no message, print truncates */
575 }
576 }
577 if (msgEnd == -1) {
578 /* incoming message not null-terminated; force it */
579 msgEnd = buf->len - 1; /* may result in msgEnd < msgStart */
580 msg[msgEnd] = '\0';
581 }
582
583 entry->priority = msg[0];
584 entry->tag = msg + 1;
585 entry->tagLen = msgStart - 1;
586 entry->message = msg + msgStart;
587 entry->messageLen = (msgEnd < msgStart) ? 0 : (msgEnd - msgStart);
588
589 return 0;
590 }
591
592 /*
593 * Extract a 4-byte value from a byte stream.
594 */
get4LE(const uint8_t * src)595 static inline uint32_t get4LE(const uint8_t* src) {
596 return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
597 }
598
599 /*
600 * Extract an 8-byte value from a byte stream.
601 */
get8LE(const uint8_t * src)602 static inline uint64_t get8LE(const uint8_t* src) {
603 uint32_t low, high;
604
605 low = src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
606 high = src[4] | (src[5] << 8) | (src[6] << 16) | (src[7] << 24);
607 return ((uint64_t)high << 32) | (uint64_t)low;
608 }
609
findChar(const char ** cp,size_t * len,int c)610 static bool findChar(const char** cp, size_t* len, int c) {
611 while ((*len) && isspace(*(*cp))) {
612 ++(*cp);
613 --(*len);
614 }
615 if (c == INT_MAX) return *len;
616 if ((*len) && (*(*cp) == c)) {
617 ++(*cp);
618 --(*len);
619 return true;
620 }
621 return false;
622 }
623
624 /*
625 * Recursively convert binary log data to printable form.
626 *
627 * This needs to be recursive because you can have lists of lists.
628 *
629 * If we run out of room, we stop processing immediately. It's important
630 * for us to check for space on every output element to avoid producing
631 * garbled output.
632 *
633 * Returns 0 on success, 1 on buffer full, -1 on failure.
634 */
635 enum objectType {
636 TYPE_OBJECTS = '1',
637 TYPE_BYTES = '2',
638 TYPE_MILLISECONDS = '3',
639 TYPE_ALLOCATIONS = '4',
640 TYPE_ID = '5',
641 TYPE_PERCENT = '6',
642 TYPE_MONOTONIC = 's'
643 };
644
android_log_printBinaryEvent(const unsigned char ** pEventData,size_t * pEventDataLen,char ** pOutBuf,size_t * pOutBufLen,const char ** fmtStr,size_t * fmtLen)645 static int android_log_printBinaryEvent(const unsigned char** pEventData,
646 size_t* pEventDataLen, char** pOutBuf,
647 size_t* pOutBufLen, const char** fmtStr,
648 size_t* fmtLen) {
649 const unsigned char* eventData = *pEventData;
650 size_t eventDataLen = *pEventDataLen;
651 char* outBuf = *pOutBuf;
652 char* outBufSave = outBuf;
653 size_t outBufLen = *pOutBufLen;
654 size_t outBufLenSave = outBufLen;
655 unsigned char type;
656 size_t outCount = 0;
657 int result = 0;
658 const char* cp;
659 size_t len;
660 int64_t lval;
661
662 if (eventDataLen < 1) return -1;
663
664 type = *eventData++;
665 eventDataLen--;
666
667 cp = NULL;
668 len = 0;
669 if (fmtStr && *fmtStr && fmtLen && *fmtLen && **fmtStr) {
670 cp = *fmtStr;
671 len = *fmtLen;
672 }
673 /*
674 * event.logtag format specification:
675 *
676 * Optionally, after the tag names can be put a description for the value(s)
677 * of the tag. Description are in the format
678 * (<name>|data type[|data unit])
679 * Multiple values are separated by commas.
680 *
681 * The data type is a number from the following values:
682 * 1: int
683 * 2: long
684 * 3: string
685 * 4: list
686 * 5: float
687 *
688 * The data unit is a number taken from the following list:
689 * 1: Number of objects
690 * 2: Number of bytes
691 * 3: Number of milliseconds
692 * 4: Number of allocations
693 * 5: Id
694 * 6: Percent
695 * s: Number of seconds (monotonic time)
696 * Default value for data of type int/long is 2 (bytes).
697 */
698 if (!cp || !findChar(&cp, &len, '(')) {
699 len = 0;
700 } else {
701 char* outBufLastSpace = NULL;
702
703 findChar(&cp, &len, INT_MAX);
704 while (len && *cp && (*cp != '|') && (*cp != ')')) {
705 if (outBufLen <= 0) {
706 /* halt output */
707 goto no_room;
708 }
709 outBufLastSpace = isspace(*cp) ? outBuf : NULL;
710 *outBuf = *cp;
711 ++outBuf;
712 ++cp;
713 --outBufLen;
714 --len;
715 }
716 if (outBufLastSpace) {
717 outBufLen += outBuf - outBufLastSpace;
718 outBuf = outBufLastSpace;
719 }
720 if (outBufLen <= 0) {
721 /* halt output */
722 goto no_room;
723 }
724 if (outBufSave != outBuf) {
725 *outBuf = '=';
726 ++outBuf;
727 --outBufLen;
728 }
729
730 if (findChar(&cp, &len, '|') && findChar(&cp, &len, INT_MAX)) {
731 static const unsigned char typeTable[] = {
732 EVENT_TYPE_INT, EVENT_TYPE_LONG, EVENT_TYPE_STRING, EVENT_TYPE_LIST,
733 EVENT_TYPE_FLOAT
734 };
735
736 if ((*cp >= '1') &&
737 (*cp < (char)('1' + (sizeof(typeTable) / sizeof(typeTable[0])))) &&
738 (type != typeTable[(size_t)(*cp - '1')]))
739 len = 0;
740
741 if (len) {
742 ++cp;
743 --len;
744 } else {
745 /* reset the format */
746 outBuf = outBufSave;
747 outBufLen = outBufLenSave;
748 }
749 }
750 }
751 outCount = 0;
752 lval = 0;
753 switch (type) {
754 case EVENT_TYPE_INT:
755 /* 32-bit signed int */
756 {
757 int32_t ival;
758
759 if (eventDataLen < 4) return -1;
760 ival = get4LE(eventData);
761 eventData += 4;
762 eventDataLen -= 4;
763
764 lval = ival;
765 }
766 goto pr_lval;
767 case EVENT_TYPE_LONG:
768 /* 64-bit signed long */
769 if (eventDataLen < 8) return -1;
770 lval = get8LE(eventData);
771 eventData += 8;
772 eventDataLen -= 8;
773 pr_lval:
774 outCount = snprintf(outBuf, outBufLen, "%" PRId64, lval);
775 if (outCount < outBufLen) {
776 outBuf += outCount;
777 outBufLen -= outCount;
778 } else {
779 /* halt output */
780 goto no_room;
781 }
782 break;
783 case EVENT_TYPE_FLOAT:
784 /* float */
785 {
786 uint32_t ival;
787 float fval;
788
789 if (eventDataLen < 4) return -1;
790 ival = get4LE(eventData);
791 fval = *(float*)&ival;
792 eventData += 4;
793 eventDataLen -= 4;
794
795 outCount = snprintf(outBuf, outBufLen, "%f", fval);
796 if (outCount < outBufLen) {
797 outBuf += outCount;
798 outBufLen -= outCount;
799 } else {
800 /* halt output */
801 goto no_room;
802 }
803 }
804 break;
805 case EVENT_TYPE_STRING:
806 /* UTF-8 chars, not NULL-terminated */
807 {
808 unsigned int strLen;
809
810 if (eventDataLen < 4) return -1;
811 strLen = get4LE(eventData);
812 eventData += 4;
813 eventDataLen -= 4;
814
815 if (eventDataLen < strLen) {
816 result = -1; /* mark truncated */
817 strLen = eventDataLen;
818 }
819
820 if (cp && (strLen == 0)) {
821 /* reset the format if no content */
822 outBuf = outBufSave;
823 outBufLen = outBufLenSave;
824 }
825 if (strLen < outBufLen) {
826 memcpy(outBuf, eventData, strLen);
827 outBuf += strLen;
828 outBufLen -= strLen;
829 } else {
830 if (outBufLen > 0) {
831 /* copy what we can */
832 memcpy(outBuf, eventData, outBufLen);
833 outBuf += outBufLen;
834 outBufLen -= outBufLen;
835 }
836 if (!result) result = 1; /* if not truncated, return no room */
837 }
838 eventData += strLen;
839 eventDataLen -= strLen;
840 if (result != 0) goto bail;
841 break;
842 }
843 case EVENT_TYPE_LIST:
844 /* N items, all different types */
845 {
846 unsigned char count;
847 int i;
848
849 if (eventDataLen < 1) return -1;
850
851 count = *eventData++;
852 eventDataLen--;
853
854 if (outBufLen <= 0) goto no_room;
855
856 *outBuf++ = '[';
857 outBufLen--;
858
859 for (i = 0; i < count; i++) {
860 result = android_log_printBinaryEvent(
861 &eventData, &eventDataLen, &outBuf, &outBufLen, fmtStr, fmtLen);
862 if (result != 0) goto bail;
863
864 if (i < (count - 1)) {
865 if (outBufLen <= 0) goto no_room;
866 *outBuf++ = ',';
867 outBufLen--;
868 }
869 }
870
871 if (outBufLen <= 0) goto no_room;
872
873 *outBuf++ = ']';
874 outBufLen--;
875 }
876 break;
877 default:
878 fprintf(stderr, "Unknown binary event type %d\n", type);
879 return -1;
880 }
881 if (cp && len) {
882 if (findChar(&cp, &len, '|') && findChar(&cp, &len, INT_MAX)) {
883 switch (*cp) {
884 case TYPE_OBJECTS:
885 outCount = 0;
886 /* outCount = snprintf(outBuf, outBufLen, " objects"); */
887 break;
888 case TYPE_BYTES:
889 if ((lval != 0) && ((lval % 1024) == 0)) {
890 /* repaint with multiplier */
891 static const char suffixTable[] = { 'K', 'M', 'G', 'T' };
892 size_t idx = 0;
893 outBuf -= outCount;
894 outBufLen += outCount;
895 do {
896 lval /= 1024;
897 if ((lval % 1024) != 0) break;
898 } while (++idx <
899 ((sizeof(suffixTable) / sizeof(suffixTable[0])) - 1));
900 outCount = snprintf(outBuf, outBufLen, "%" PRId64 "%cB", lval,
901 suffixTable[idx]);
902 } else {
903 outCount = snprintf(outBuf, outBufLen, "B");
904 }
905 break;
906 case TYPE_MILLISECONDS:
907 if (((lval <= -1000) || (1000 <= lval)) &&
908 (outBufLen || (outBuf[-1] == '0'))) {
909 /* repaint as (fractional) seconds, possibly saving space */
910 if (outBufLen) outBuf[0] = outBuf[-1];
911 outBuf[-1] = outBuf[-2];
912 outBuf[-2] = outBuf[-3];
913 outBuf[-3] = '.';
914 while ((outBufLen == 0) || (*outBuf == '0')) {
915 --outBuf;
916 ++outBufLen;
917 }
918 if (*outBuf != '.') {
919 ++outBuf;
920 --outBufLen;
921 }
922 outCount = snprintf(outBuf, outBufLen, "s");
923 } else {
924 outCount = snprintf(outBuf, outBufLen, "ms");
925 }
926 break;
927 case TYPE_MONOTONIC: {
928 static const uint64_t minute = 60;
929 static const uint64_t hour = 60 * minute;
930 static const uint64_t day = 24 * hour;
931
932 /* Repaint as unsigned seconds, minutes, hours ... */
933 outBuf -= outCount;
934 outBufLen += outCount;
935 uint64_t val = lval;
936 if (val >= day) {
937 outCount = snprintf(outBuf, outBufLen, "%" PRIu64 "d ", val / day);
938 if (outCount >= outBufLen) break;
939 outBuf += outCount;
940 outBufLen -= outCount;
941 val = (val % day) + day;
942 }
943 if (val >= minute) {
944 if (val >= hour) {
945 outCount = snprintf(outBuf, outBufLen, "%" PRIu64 ":",
946 (val / hour) % (day / hour));
947 if (outCount >= outBufLen) break;
948 outBuf += outCount;
949 outBufLen -= outCount;
950 }
951 outCount =
952 snprintf(outBuf, outBufLen,
953 (val >= hour) ? "%02" PRIu64 ":" : "%" PRIu64 ":",
954 (val / minute) % (hour / minute));
955 if (outCount >= outBufLen) break;
956 outBuf += outCount;
957 outBufLen -= outCount;
958 }
959 outCount = snprintf(outBuf, outBufLen,
960 (val >= minute) ? "%02" PRIu64 : "%" PRIu64 "s",
961 val % minute);
962 } break;
963 case TYPE_ALLOCATIONS:
964 outCount = 0;
965 /* outCount = snprintf(outBuf, outBufLen, " allocations"); */
966 break;
967 case TYPE_ID:
968 outCount = 0;
969 break;
970 case TYPE_PERCENT:
971 outCount = snprintf(outBuf, outBufLen, "%%");
972 break;
973 default: /* ? */
974 outCount = 0;
975 break;
976 }
977 ++cp;
978 --len;
979 if (outCount < outBufLen) {
980 outBuf += outCount;
981 outBufLen -= outCount;
982 } else if (outCount) {
983 /* halt output */
984 goto no_room;
985 }
986 }
987 if (!findChar(&cp, &len, ')')) len = 0;
988 if (!findChar(&cp, &len, ',')) len = 0;
989 }
990
991 bail:
992 *pEventData = eventData;
993 *pEventDataLen = eventDataLen;
994 *pOutBuf = outBuf;
995 *pOutBufLen = outBufLen;
996 if (cp) {
997 *fmtStr = cp;
998 *fmtLen = len;
999 }
1000 return result;
1001
1002 no_room:
1003 result = 1;
1004 goto bail;
1005 }
1006
1007 /**
1008 * Convert a binary log entry to ASCII form.
1009 *
1010 * For convenience we mimic the processLogBuffer API. There is no
1011 * pre-defined output length for the binary data, since we're free to format
1012 * it however we choose, which means we can't really use a fixed-size buffer
1013 * here.
1014 */
android_log_processBinaryLogBuffer(struct logger_entry * buf,AndroidLogEntry * entry,const EventTagMap * map __unused,char * messageBuf,int messageBufLen)1015 LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer(
1016 struct logger_entry* buf, AndroidLogEntry* entry,
1017 const EventTagMap* map __unused, /* only on !__ANDROID__ */
1018 char* messageBuf, int messageBufLen) {
1019 size_t inCount;
1020 uint32_t tagIndex;
1021 const unsigned char* eventData;
1022
1023 entry->message = NULL;
1024 entry->messageLen = 0;
1025
1026 entry->tv_sec = buf->sec;
1027 entry->tv_nsec = buf->nsec;
1028 entry->priority = ANDROID_LOG_INFO;
1029 entry->uid = -1;
1030 entry->pid = buf->pid;
1031 entry->tid = buf->tid;
1032
1033 /*
1034 * Pull the tag out, fill in some additional details based on incoming
1035 * buffer version (v3 adds lid, v4 adds uid).
1036 */
1037 eventData = (const unsigned char*)buf->msg;
1038 struct logger_entry_v2* buf2 = (struct logger_entry_v2*)buf;
1039 if (buf2->hdr_size) {
1040 if ((buf2->hdr_size < sizeof(((struct log_msg*)NULL)->entry_v1)) ||
1041 (buf2->hdr_size > sizeof(((struct log_msg*)NULL)->entry))) {
1042 fprintf(stderr, "+++ LOG: entry illegal hdr_size\n");
1043 return -1;
1044 }
1045 eventData = ((unsigned char*)buf2) + buf2->hdr_size;
1046 if ((buf2->hdr_size >= sizeof(struct logger_entry_v3)) &&
1047 (((struct logger_entry_v3*)buf)->lid == LOG_ID_SECURITY)) {
1048 entry->priority = ANDROID_LOG_WARN;
1049 }
1050 if (buf2->hdr_size >= sizeof(struct logger_entry_v4)) {
1051 entry->uid = ((struct logger_entry_v4*)buf)->uid;
1052 }
1053 }
1054 inCount = buf->len;
1055 if (inCount < 4) return -1;
1056 tagIndex = get4LE(eventData);
1057 eventData += 4;
1058 inCount -= 4;
1059
1060 entry->tagLen = 0;
1061 entry->tag = NULL;
1062 #ifdef __ANDROID__
1063 if (map != NULL) {
1064 entry->tag = android_lookupEventTag_len(map, &entry->tagLen, tagIndex);
1065 }
1066 #endif
1067
1068 /*
1069 * If we don't have a map, or didn't find the tag number in the map,
1070 * stuff a generated tag value into the start of the output buffer and
1071 * shift the buffer pointers down.
1072 */
1073 if (entry->tag == NULL) {
1074 size_t tagLen;
1075
1076 tagLen = snprintf(messageBuf, messageBufLen, "[%" PRIu32 "]", tagIndex);
1077 if (tagLen >= (size_t)messageBufLen) {
1078 tagLen = messageBufLen - 1;
1079 }
1080 entry->tag = messageBuf;
1081 entry->tagLen = tagLen;
1082 messageBuf += tagLen + 1;
1083 messageBufLen -= tagLen + 1;
1084 }
1085
1086 /*
1087 * Format the event log data into the buffer.
1088 */
1089 const char* fmtStr = NULL;
1090 size_t fmtLen = 0;
1091 #ifdef __ANDROID__
1092 if (descriptive_output && map) {
1093 fmtStr = android_lookupEventFormat_len(map, &fmtLen, tagIndex);
1094 }
1095 #endif
1096
1097 char* outBuf = messageBuf;
1098 size_t outRemaining = messageBufLen - 1; /* leave one for nul byte */
1099 int result = 0;
1100
1101 if ((inCount > 0) || fmtLen) {
1102 result = android_log_printBinaryEvent(&eventData, &inCount, &outBuf,
1103 &outRemaining, &fmtStr, &fmtLen);
1104 }
1105 if ((result == 1) && fmtStr) {
1106 /* We overflowed :-(, let's repaint the line w/o format dressings */
1107 eventData = (const unsigned char*)buf->msg;
1108 if (buf2->hdr_size) {
1109 eventData = ((unsigned char*)buf2) + buf2->hdr_size;
1110 }
1111 eventData += 4;
1112 outBuf = messageBuf;
1113 outRemaining = messageBufLen - 1;
1114 result = android_log_printBinaryEvent(&eventData, &inCount, &outBuf,
1115 &outRemaining, NULL, NULL);
1116 }
1117 if (result < 0) {
1118 fprintf(stderr, "Binary log entry conversion failed\n");
1119 }
1120 if (result) {
1121 if (!outRemaining) {
1122 /* make space to leave an indicator */
1123 --outBuf;
1124 ++outRemaining;
1125 }
1126 *outBuf++ = (result < 0) ? '!' : '^'; /* Error or Truncation? */
1127 outRemaining--;
1128 /* pretend we ate all the data to prevent log stutter */
1129 inCount = 0;
1130 if (result > 0) result = 0;
1131 }
1132
1133 /* eat the silly terminating '\n' */
1134 if (inCount == 1 && *eventData == '\n') {
1135 eventData++;
1136 inCount--;
1137 }
1138
1139 if (inCount != 0) {
1140 fprintf(stderr, "Warning: leftover binary log data (%zu bytes)\n", inCount);
1141 }
1142
1143 /*
1144 * Terminate the buffer. The NUL byte does not count as part of
1145 * entry->messageLen.
1146 */
1147 *outBuf = '\0';
1148 entry->messageLen = outBuf - messageBuf;
1149 assert(entry->messageLen == (messageBufLen - 1) - outRemaining);
1150
1151 entry->message = messageBuf;
1152
1153 return result;
1154 }
1155
1156 /*
1157 * One utf8 character at a time
1158 *
1159 * Returns the length of the utf8 character in the buffer,
1160 * or -1 if illegal or truncated
1161 *
1162 * Open coded from libutils/Unicode.cpp, borrowed from utf8_length(),
1163 * can not remove from here because of library circular dependencies.
1164 * Expect one-day utf8_character_length with the same signature could
1165 * _also_ be part of libutils/Unicode.cpp if its usefullness needs to
1166 * propagate globally.
1167 */
utf8_character_length(const char * src,size_t len)1168 LIBLOG_WEAK ssize_t utf8_character_length(const char* src, size_t len) {
1169 const char* cur = src;
1170 const char first_char = *cur++;
1171 static const uint32_t kUnicodeMaxCodepoint = 0x0010FFFF;
1172 int32_t mask, to_ignore_mask;
1173 size_t num_to_read;
1174 uint32_t utf32;
1175
1176 if ((first_char & 0x80) == 0) { /* ASCII */
1177 return first_char ? 1 : -1;
1178 }
1179
1180 /*
1181 * (UTF-8's character must not be like 10xxxxxx,
1182 * but 110xxxxx, 1110xxxx, ... or 1111110x)
1183 */
1184 if ((first_char & 0x40) == 0) {
1185 return -1;
1186 }
1187
1188 for (utf32 = 1, num_to_read = 1, mask = 0x40, to_ignore_mask = 0x80;
1189 num_to_read < 5 && (first_char & mask);
1190 num_to_read++, to_ignore_mask |= mask, mask >>= 1) {
1191 if (num_to_read > len) {
1192 return -1;
1193 }
1194 if ((*cur & 0xC0) != 0x80) { /* can not be 10xxxxxx? */
1195 return -1;
1196 }
1197 utf32 = (utf32 << 6) + (*cur++ & 0b00111111);
1198 }
1199 /* "first_char" must be (110xxxxx - 11110xxx) */
1200 if (num_to_read >= 5) {
1201 return -1;
1202 }
1203 to_ignore_mask |= mask;
1204 utf32 |= ((~to_ignore_mask) & first_char) << (6 * (num_to_read - 1));
1205 if (utf32 > kUnicodeMaxCodepoint) {
1206 return -1;
1207 }
1208 return num_to_read;
1209 }
1210
1211 /*
1212 * Convert to printable from message to p buffer, return string length. If p is
1213 * NULL, do not copy, but still return the expected string length.
1214 */
convertPrintable(char * p,const char * message,size_t messageLen)1215 static size_t convertPrintable(char* p, const char* message, size_t messageLen) {
1216 char* begin = p;
1217 bool print = p != NULL;
1218
1219 while (messageLen) {
1220 char buf[6];
1221 ssize_t len = sizeof(buf) - 1;
1222 if ((size_t)len > messageLen) {
1223 len = messageLen;
1224 }
1225 len = utf8_character_length(message, len);
1226
1227 if (len < 0) {
1228 snprintf(buf, sizeof(buf),
1229 ((messageLen > 1) && isdigit(message[1])) ? "\\%03o" : "\\%o",
1230 *message & 0377);
1231 len = 1;
1232 } else {
1233 buf[0] = '\0';
1234 if (len == 1) {
1235 if (*message == '\a') {
1236 strcpy(buf, "\\a");
1237 } else if (*message == '\b') {
1238 strcpy(buf, "\\b");
1239 } else if (*message == '\t') {
1240 strcpy(buf, "\t"); /* Do not escape tabs */
1241 } else if (*message == '\v') {
1242 strcpy(buf, "\\v");
1243 } else if (*message == '\f') {
1244 strcpy(buf, "\\f");
1245 } else if (*message == '\r') {
1246 strcpy(buf, "\\r");
1247 } else if (*message == '\\') {
1248 strcpy(buf, "\\\\");
1249 } else if ((*message < ' ') || (*message & 0x80)) {
1250 snprintf(buf, sizeof(buf), "\\%o", *message & 0377);
1251 }
1252 }
1253 if (!buf[0]) {
1254 strncpy(buf, message, len);
1255 buf[len] = '\0';
1256 }
1257 }
1258 if (print) {
1259 strcpy(p, buf);
1260 }
1261 p += strlen(buf);
1262 message += len;
1263 messageLen -= len;
1264 }
1265 return p - begin;
1266 }
1267
readSeconds(char * e,struct timespec * t)1268 static char* readSeconds(char* e, struct timespec* t) {
1269 unsigned long multiplier;
1270 char* p;
1271 t->tv_sec = strtoul(e, &p, 10);
1272 if (*p != '.') {
1273 return NULL;
1274 }
1275 t->tv_nsec = 0;
1276 multiplier = NS_PER_SEC;
1277 while (isdigit(*++p) && (multiplier /= 10)) {
1278 t->tv_nsec += (*p - '0') * multiplier;
1279 }
1280 return p;
1281 }
1282
sumTimespec(struct timespec * left,struct timespec * right)1283 static struct timespec* sumTimespec(struct timespec* left,
1284 struct timespec* right) {
1285 left->tv_nsec += right->tv_nsec;
1286 left->tv_sec += right->tv_sec;
1287 if (left->tv_nsec >= (long)NS_PER_SEC) {
1288 left->tv_nsec -= NS_PER_SEC;
1289 left->tv_sec += 1;
1290 }
1291 return left;
1292 }
1293
subTimespec(struct timespec * result,struct timespec * left,struct timespec * right)1294 static struct timespec* subTimespec(struct timespec* result,
1295 struct timespec* left,
1296 struct timespec* right) {
1297 result->tv_nsec = left->tv_nsec - right->tv_nsec;
1298 result->tv_sec = left->tv_sec - right->tv_sec;
1299 if (result->tv_nsec < 0) {
1300 result->tv_nsec += NS_PER_SEC;
1301 result->tv_sec -= 1;
1302 }
1303 return result;
1304 }
1305
nsecTimespec(struct timespec * now)1306 static long long nsecTimespec(struct timespec* now) {
1307 return (long long)now->tv_sec * NS_PER_SEC + now->tv_nsec;
1308 }
1309
1310 #ifdef __ANDROID__
convertMonotonic(struct timespec * result,const AndroidLogEntry * entry)1311 static void convertMonotonic(struct timespec* result,
1312 const AndroidLogEntry* entry) {
1313 struct listnode* node;
1314 struct conversionList {
1315 struct listnode node; /* first */
1316 struct timespec time;
1317 struct timespec convert;
1318 } * list, *next;
1319 struct timespec time, convert;
1320
1321 /* If we do not have a conversion list, build one up */
1322 if (list_empty(&convertHead)) {
1323 bool suspended_pending = false;
1324 struct timespec suspended_monotonic = { 0, 0 };
1325 struct timespec suspended_diff = { 0, 0 };
1326
1327 /*
1328 * Read dmesg for _some_ synchronization markers and insert
1329 * Anything in the Android Logger before the dmesg logging span will
1330 * be highly suspect regarding the monotonic time calculations.
1331 */
1332 FILE* p = popen("/system/bin/dmesg", "re");
1333 if (p) {
1334 char* line = NULL;
1335 size_t len = 0;
1336 while (getline(&line, &len, p) > 0) {
1337 static const char suspend[] = "PM: suspend entry ";
1338 static const char resume[] = "PM: suspend exit ";
1339 static const char healthd[] = "healthd";
1340 static const char battery[] = ": battery ";
1341 static const char suspended[] = "Suspended for ";
1342 struct timespec monotonic;
1343 struct tm tm;
1344 char *cp, *e = line;
1345 bool add_entry = true;
1346
1347 if (*e == '<') {
1348 while (*e && (*e != '>')) {
1349 ++e;
1350 }
1351 if (*e != '>') {
1352 continue;
1353 }
1354 }
1355 if (*e != '[') {
1356 continue;
1357 }
1358 while (*++e == ' ') {
1359 ;
1360 }
1361 e = readSeconds(e, &monotonic);
1362 if (!e || (*e != ']')) {
1363 continue;
1364 }
1365
1366 if ((e = strstr(e, suspend))) {
1367 e += sizeof(suspend) - 1;
1368 } else if ((e = strstr(line, resume))) {
1369 e += sizeof(resume) - 1;
1370 } else if (((e = strstr(line, healthd))) &&
1371 ((e = strstr(e + sizeof(healthd) - 1, battery)))) {
1372 /* NB: healthd is roughly 150us late, worth the price to
1373 * deal with ntp-induced or hardware clock drift. */
1374 e += sizeof(battery) - 1;
1375 } else if ((e = strstr(line, suspended))) {
1376 e += sizeof(suspended) - 1;
1377 e = readSeconds(e, &time);
1378 if (!e) {
1379 continue;
1380 }
1381 add_entry = false;
1382 suspended_pending = true;
1383 suspended_monotonic = monotonic;
1384 suspended_diff = time;
1385 } else {
1386 continue;
1387 }
1388 if (add_entry) {
1389 /* look for "????-??-?? ??:??:??.????????? UTC" */
1390 cp = strstr(e, " UTC");
1391 if (!cp || ((cp - e) < 29) || (cp[-10] != '.')) {
1392 continue;
1393 }
1394 e = cp - 29;
1395 cp = readSeconds(cp - 10, &time);
1396 if (!cp) {
1397 continue;
1398 }
1399 cp = strptime(e, "%Y-%m-%d %H:%M:%S.", &tm);
1400 if (!cp) {
1401 continue;
1402 }
1403 cp = getenv(tz);
1404 if (cp) {
1405 cp = strdup(cp);
1406 }
1407 setenv(tz, utc, 1);
1408 time.tv_sec = mktime(&tm);
1409 if (cp) {
1410 setenv(tz, cp, 1);
1411 free(cp);
1412 } else {
1413 unsetenv(tz);
1414 }
1415 list = calloc(1, sizeof(struct conversionList));
1416 list_init(&list->node);
1417 list->time = time;
1418 subTimespec(&list->convert, &time, &monotonic);
1419 list_add_tail(&convertHead, &list->node);
1420 }
1421 if (suspended_pending && !list_empty(&convertHead)) {
1422 list = node_to_item(list_tail(&convertHead), struct conversionList,
1423 node);
1424 if (subTimespec(&time, subTimespec(&time, &list->time, &list->convert),
1425 &suspended_monotonic)
1426 ->tv_sec > 0) {
1427 /* resume, what is convert factor before? */
1428 subTimespec(&convert, &list->convert, &suspended_diff);
1429 } else {
1430 /* suspend */
1431 convert = list->convert;
1432 }
1433 time = suspended_monotonic;
1434 sumTimespec(&time, &convert);
1435 /* breakpoint just before sleep */
1436 list = calloc(1, sizeof(struct conversionList));
1437 list_init(&list->node);
1438 list->time = time;
1439 list->convert = convert;
1440 list_add_tail(&convertHead, &list->node);
1441 /* breakpoint just after sleep */
1442 list = calloc(1, sizeof(struct conversionList));
1443 list_init(&list->node);
1444 list->time = time;
1445 sumTimespec(&list->time, &suspended_diff);
1446 list->convert = convert;
1447 sumTimespec(&list->convert, &suspended_diff);
1448 list_add_tail(&convertHead, &list->node);
1449 suspended_pending = false;
1450 }
1451 }
1452 pclose(p);
1453 }
1454 /* last entry is our current time conversion */
1455 list = calloc(1, sizeof(struct conversionList));
1456 list_init(&list->node);
1457 clock_gettime(CLOCK_REALTIME, &list->time);
1458 clock_gettime(CLOCK_MONOTONIC, &convert);
1459 clock_gettime(CLOCK_MONOTONIC, &time);
1460 /* Correct for instant clock_gettime latency (syscall or ~30ns) */
1461 subTimespec(&time, &convert, subTimespec(&time, &time, &convert));
1462 /* Calculate conversion factor */
1463 subTimespec(&list->convert, &list->time, &time);
1464 list_add_tail(&convertHead, &list->node);
1465 if (suspended_pending) {
1466 /* manufacture a suspend @ point before */
1467 subTimespec(&convert, &list->convert, &suspended_diff);
1468 time = suspended_monotonic;
1469 sumTimespec(&time, &convert);
1470 /* breakpoint just after sleep */
1471 list = calloc(1, sizeof(struct conversionList));
1472 list_init(&list->node);
1473 list->time = time;
1474 sumTimespec(&list->time, &suspended_diff);
1475 list->convert = convert;
1476 sumTimespec(&list->convert, &suspended_diff);
1477 list_add_head(&convertHead, &list->node);
1478 /* breakpoint just before sleep */
1479 list = calloc(1, sizeof(struct conversionList));
1480 list_init(&list->node);
1481 list->time = time;
1482 list->convert = convert;
1483 list_add_head(&convertHead, &list->node);
1484 }
1485 }
1486
1487 /* Find the breakpoint in the conversion list */
1488 list = node_to_item(list_head(&convertHead), struct conversionList, node);
1489 next = NULL;
1490 list_for_each(node, &convertHead) {
1491 next = node_to_item(node, struct conversionList, node);
1492 if (entry->tv_sec < next->time.tv_sec) {
1493 break;
1494 } else if (entry->tv_sec == next->time.tv_sec) {
1495 if (entry->tv_nsec < next->time.tv_nsec) {
1496 break;
1497 }
1498 }
1499 list = next;
1500 }
1501
1502 /* blend time from one breakpoint to the next */
1503 convert = list->convert;
1504 if (next) {
1505 unsigned long long total, run;
1506
1507 total = nsecTimespec(subTimespec(&time, &next->time, &list->time));
1508 time.tv_sec = entry->tv_sec;
1509 time.tv_nsec = entry->tv_nsec;
1510 run = nsecTimespec(subTimespec(&time, &time, &list->time));
1511 if (run < total) {
1512 long long crun;
1513
1514 float f = nsecTimespec(subTimespec(&time, &next->convert, &convert));
1515 f *= run;
1516 f /= total;
1517 crun = f;
1518 convert.tv_sec += crun / (long long)NS_PER_SEC;
1519 if (crun < 0) {
1520 convert.tv_nsec -= (-crun) % NS_PER_SEC;
1521 if (convert.tv_nsec < 0) {
1522 convert.tv_nsec += NS_PER_SEC;
1523 convert.tv_sec -= 1;
1524 }
1525 } else {
1526 convert.tv_nsec += crun % NS_PER_SEC;
1527 if (convert.tv_nsec >= (long)NS_PER_SEC) {
1528 convert.tv_nsec -= NS_PER_SEC;
1529 convert.tv_sec += 1;
1530 }
1531 }
1532 }
1533 }
1534
1535 /* Apply the correction factor */
1536 result->tv_sec = entry->tv_sec;
1537 result->tv_nsec = entry->tv_nsec;
1538 subTimespec(result, result, &convert);
1539 }
1540 #endif
1541
1542 /**
1543 * Formats a log message into a buffer
1544 *
1545 * Uses defaultBuffer if it can, otherwise malloc()'s a new buffer
1546 * If return value != defaultBuffer, caller must call free()
1547 * Returns NULL on malloc error
1548 */
1549
android_log_formatLogLine(AndroidLogFormat * p_format,char * defaultBuffer,size_t defaultBufferSize,const AndroidLogEntry * entry,size_t * p_outLength)1550 LIBLOG_ABI_PUBLIC char* android_log_formatLogLine(AndroidLogFormat* p_format,
1551 char* defaultBuffer,
1552 size_t defaultBufferSize,
1553 const AndroidLogEntry* entry,
1554 size_t* p_outLength) {
1555 #if !defined(_WIN32)
1556 struct tm tmBuf;
1557 #endif
1558 struct tm* ptm;
1559 /* good margin, 23+nul for msec, 26+nul for usec, 29+nul to nsec */
1560 char timeBuf[64];
1561 char prefixBuf[128], suffixBuf[128];
1562 char priChar;
1563 int prefixSuffixIsHeaderFooter = 0;
1564 char* ret;
1565 time_t now;
1566 unsigned long nsec;
1567
1568 priChar = filterPriToChar(entry->priority);
1569 size_t prefixLen = 0, suffixLen = 0;
1570 size_t len;
1571
1572 /*
1573 * Get the current date/time in pretty form
1574 *
1575 * It's often useful when examining a log with "less" to jump to
1576 * a specific point in the file by searching for the date/time stamp.
1577 * For this reason it's very annoying to have regexp meta characters
1578 * in the time stamp. Don't use forward slashes, parenthesis,
1579 * brackets, asterisks, or other special chars here.
1580 *
1581 * The caller may have affected the timezone environment, this is
1582 * expected to be sensitive to that.
1583 */
1584 now = entry->tv_sec;
1585 nsec = entry->tv_nsec;
1586 #if __ANDROID__
1587 if (p_format->monotonic_output) {
1588 /* prevent convertMonotonic from being called if logd is monotonic */
1589 if (android_log_clockid() != CLOCK_MONOTONIC) {
1590 struct timespec time;
1591 convertMonotonic(&time, entry);
1592 now = time.tv_sec;
1593 nsec = time.tv_nsec;
1594 }
1595 }
1596 #endif
1597 if (now < 0) {
1598 nsec = NS_PER_SEC - nsec;
1599 }
1600 if (p_format->epoch_output || p_format->monotonic_output) {
1601 ptm = NULL;
1602 snprintf(timeBuf, sizeof(timeBuf),
1603 p_format->monotonic_output ? "%6lld" : "%19lld", (long long)now);
1604 } else {
1605 #if !defined(_WIN32)
1606 ptm = localtime_r(&now, &tmBuf);
1607 #else
1608 ptm = localtime(&now);
1609 #endif
1610 strftime(timeBuf, sizeof(timeBuf),
1611 &"%Y-%m-%d %H:%M:%S"[p_format->year_output ? 0 : 3], ptm);
1612 }
1613 len = strlen(timeBuf);
1614 if (p_format->nsec_time_output) {
1615 len += snprintf(timeBuf + len, sizeof(timeBuf) - len, ".%09ld", nsec);
1616 } else if (p_format->usec_time_output) {
1617 len += snprintf(timeBuf + len, sizeof(timeBuf) - len, ".%06ld",
1618 nsec / US_PER_NSEC);
1619 } else {
1620 len += snprintf(timeBuf + len, sizeof(timeBuf) - len, ".%03ld",
1621 nsec / MS_PER_NSEC);
1622 }
1623 if (p_format->zone_output && ptm) {
1624 strftime(timeBuf + len, sizeof(timeBuf) - len, " %z", ptm);
1625 }
1626
1627 /*
1628 * Construct a buffer containing the log header and log message.
1629 */
1630 if (p_format->colored_output) {
1631 prefixLen = snprintf(prefixBuf, sizeof(prefixBuf), "\x1B[38;5;%dm",
1632 colorFromPri(entry->priority));
1633 prefixLen = MIN(prefixLen, sizeof(prefixBuf));
1634 suffixLen = snprintf(suffixBuf, sizeof(suffixBuf), "\x1B[0m");
1635 suffixLen = MIN(suffixLen, sizeof(suffixBuf));
1636 }
1637
1638 char uid[16];
1639 uid[0] = '\0';
1640 if (p_format->uid_output) {
1641 if (entry->uid >= 0) {
1642 /*
1643 * This code is Android specific, bionic guarantees that
1644 * calls to non-reentrant getpwuid() are thread safe.
1645 */
1646 #if !defined(__MINGW32__)
1647 #if (FAKE_LOG_DEVICE == 0)
1648 #ifndef __BIONIC__
1649 #warning \
1650 "This code assumes that getpwuid is thread safe, only true with Bionic!"
1651 #endif
1652 #endif
1653 struct passwd* pwd = getpwuid(entry->uid);
1654 if (pwd && (strlen(pwd->pw_name) <= 5)) {
1655 snprintf(uid, sizeof(uid), "%5s:", pwd->pw_name);
1656 } else
1657 #endif
1658 {
1659 /* Not worth parsing package list, names all longer than 5 */
1660 snprintf(uid, sizeof(uid), "%5d:", entry->uid);
1661 }
1662 } else {
1663 snprintf(uid, sizeof(uid), " ");
1664 }
1665 }
1666
1667 switch (p_format->format) {
1668 case FORMAT_TAG:
1669 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1670 "%c/%-8.*s: ", priChar, (int)entry->tagLen, entry->tag);
1671 strcpy(suffixBuf + suffixLen, "\n");
1672 ++suffixLen;
1673 break;
1674 case FORMAT_PROCESS:
1675 len = snprintf(suffixBuf + suffixLen, sizeof(suffixBuf) - suffixLen,
1676 " (%.*s)\n", (int)entry->tagLen, entry->tag);
1677 suffixLen += MIN(len, sizeof(suffixBuf) - suffixLen);
1678 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1679 "%c(%s%5d) ", priChar, uid, entry->pid);
1680 break;
1681 case FORMAT_THREAD:
1682 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1683 "%c(%s%5d:%5d) ", priChar, uid, entry->pid, entry->tid);
1684 strcpy(suffixBuf + suffixLen, "\n");
1685 ++suffixLen;
1686 break;
1687 case FORMAT_RAW:
1688 prefixBuf[prefixLen] = 0;
1689 len = 0;
1690 strcpy(suffixBuf + suffixLen, "\n");
1691 ++suffixLen;
1692 break;
1693 case FORMAT_TIME:
1694 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1695 "%s %c/%-8.*s(%s%5d): ", timeBuf, priChar,
1696 (int)entry->tagLen, entry->tag, uid, entry->pid);
1697 strcpy(suffixBuf + suffixLen, "\n");
1698 ++suffixLen;
1699 break;
1700 case FORMAT_THREADTIME:
1701 ret = strchr(uid, ':');
1702 if (ret) {
1703 *ret = ' ';
1704 }
1705 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1706 "%s %s%5d %5d %c %-8.*s: ", timeBuf, uid, entry->pid,
1707 entry->tid, priChar, (int)entry->tagLen, entry->tag);
1708 strcpy(suffixBuf + suffixLen, "\n");
1709 ++suffixLen;
1710 break;
1711 case FORMAT_LONG:
1712 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1713 "[ %s %s%5d:%5d %c/%-8.*s ]\n", timeBuf, uid, entry->pid,
1714 entry->tid, priChar, (int)entry->tagLen, entry->tag);
1715 strcpy(suffixBuf + suffixLen, "\n\n");
1716 suffixLen += 2;
1717 prefixSuffixIsHeaderFooter = 1;
1718 break;
1719 case FORMAT_BRIEF:
1720 default:
1721 len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1722 "%c/%-8.*s(%s%5d): ", priChar, (int)entry->tagLen,
1723 entry->tag, uid, entry->pid);
1724 strcpy(suffixBuf + suffixLen, "\n");
1725 ++suffixLen;
1726 break;
1727 }
1728
1729 /* snprintf has a weird return value. It returns what would have been
1730 * written given a large enough buffer. In the case that the prefix is
1731 * longer then our buffer(128), it messes up the calculations below
1732 * possibly causing heap corruption. To avoid this we double check and
1733 * set the length at the maximum (size minus null byte)
1734 */
1735 prefixLen += len;
1736 if (prefixLen >= sizeof(prefixBuf)) {
1737 prefixLen = sizeof(prefixBuf) - 1;
1738 prefixBuf[sizeof(prefixBuf) - 1] = '\0';
1739 }
1740 if (suffixLen >= sizeof(suffixBuf)) {
1741 suffixLen = sizeof(suffixBuf) - 1;
1742 suffixBuf[sizeof(suffixBuf) - 2] = '\n';
1743 suffixBuf[sizeof(suffixBuf) - 1] = '\0';
1744 }
1745
1746 /* the following code is tragically unreadable */
1747
1748 size_t numLines;
1749 char* p;
1750 size_t bufferSize;
1751 const char* pm;
1752
1753 if (prefixSuffixIsHeaderFooter) {
1754 /* we're just wrapping message with a header/footer */
1755 numLines = 1;
1756 } else {
1757 pm = entry->message;
1758 numLines = 0;
1759
1760 /*
1761 * The line-end finding here must match the line-end finding
1762 * in for ( ... numLines...) loop below
1763 */
1764 while (pm < (entry->message + entry->messageLen)) {
1765 if (*pm++ == '\n') numLines++;
1766 }
1767 /* plus one line for anything not newline-terminated at the end */
1768 if (pm > entry->message && *(pm - 1) != '\n') numLines++;
1769 }
1770
1771 /*
1772 * this is an upper bound--newlines in message may be counted
1773 * extraneously
1774 */
1775 bufferSize = (numLines * (prefixLen + suffixLen)) + 1;
1776 if (p_format->printable_output) {
1777 /* Calculate extra length to convert non-printable to printable */
1778 bufferSize += convertPrintable(NULL, entry->message, entry->messageLen);
1779 } else {
1780 bufferSize += entry->messageLen;
1781 }
1782
1783 if (defaultBufferSize >= bufferSize) {
1784 ret = defaultBuffer;
1785 } else {
1786 ret = (char*)malloc(bufferSize);
1787
1788 if (ret == NULL) {
1789 return ret;
1790 }
1791 }
1792
1793 ret[0] = '\0'; /* to start strcat off */
1794
1795 p = ret;
1796 pm = entry->message;
1797
1798 if (prefixSuffixIsHeaderFooter) {
1799 strcat(p, prefixBuf);
1800 p += prefixLen;
1801 if (p_format->printable_output) {
1802 p += convertPrintable(p, entry->message, entry->messageLen);
1803 } else {
1804 strncat(p, entry->message, entry->messageLen);
1805 p += entry->messageLen;
1806 }
1807 strcat(p, suffixBuf);
1808 p += suffixLen;
1809 } else {
1810 do {
1811 const char* lineStart;
1812 size_t lineLen;
1813 lineStart = pm;
1814
1815 /* Find the next end-of-line in message */
1816 while (pm < (entry->message + entry->messageLen) && *pm != '\n') pm++;
1817 lineLen = pm - lineStart;
1818
1819 strcat(p, prefixBuf);
1820 p += prefixLen;
1821 if (p_format->printable_output) {
1822 p += convertPrintable(p, lineStart, lineLen);
1823 } else {
1824 strncat(p, lineStart, lineLen);
1825 p += lineLen;
1826 }
1827 strcat(p, suffixBuf);
1828 p += suffixLen;
1829
1830 if (*pm == '\n') pm++;
1831 } while (pm < (entry->message + entry->messageLen));
1832 }
1833
1834 if (p_outLength != NULL) {
1835 *p_outLength = p - ret;
1836 }
1837
1838 return ret;
1839 }
1840
1841 /**
1842 * Either print or do not print log line, based on filter
1843 *
1844 * Returns count bytes written
1845 */
1846
android_log_printLogLine(AndroidLogFormat * p_format,int fd,const AndroidLogEntry * entry)1847 LIBLOG_ABI_PUBLIC int android_log_printLogLine(AndroidLogFormat* p_format,
1848 int fd,
1849 const AndroidLogEntry* entry) {
1850 int ret;
1851 char defaultBuffer[512];
1852 char* outBuffer = NULL;
1853 size_t totalLen;
1854
1855 outBuffer = android_log_formatLogLine(
1856 p_format, defaultBuffer, sizeof(defaultBuffer), entry, &totalLen);
1857
1858 if (!outBuffer) return -1;
1859
1860 do {
1861 ret = write(fd, outBuffer, totalLen);
1862 } while (ret < 0 && errno == EINTR);
1863
1864 if (ret < 0) {
1865 fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
1866 ret = 0;
1867 goto done;
1868 }
1869
1870 if (((size_t)ret) < totalLen) {
1871 fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", ret, (int)totalLen);
1872 goto done;
1873 }
1874
1875 done:
1876 if (outBuffer != defaultBuffer) {
1877 free(outBuffer);
1878 }
1879
1880 return ret;
1881 }
1882