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