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