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