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