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