1 /* 2 * Copyright (C) 2014 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 #include <ctype.h> 18 #include <errno.h> 19 #include <inttypes.h> 20 #include <limits.h> 21 #include <stdarg.h> 22 #include <stdlib.h> 23 #include <string.h> 24 #include <sys/prctl.h> 25 #include <sys/uio.h> 26 #include <syslog.h> 27 28 #include <log/logger.h> 29 #include <private/android_filesystem_config.h> 30 31 #include "LogBuffer.h" 32 #include "LogKlog.h" 33 #include "LogReader.h" 34 35 #define KMSG_PRIORITY(PRI) \ 36 '<', \ 37 '0' + (LOG_SYSLOG | (PRI)) / 10, \ 38 '0' + (LOG_SYSLOG | (PRI)) % 10, \ 39 '>' 40 41 static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' }; 42 43 // Parsing is hard 44 45 // called if we see a '<', s is the next character, returns pointer after '>' 46 static char *is_prio(char *s, size_t len) { 47 if (!len || !isdigit(*s++)) { 48 return NULL; 49 } 50 --len; 51 static const size_t max_prio_len = (len < 4) ? len : 4; 52 size_t priolen = 0; 53 char c; 54 while (((c = *s++)) && (++priolen <= max_prio_len)) { 55 if (!isdigit(c)) { 56 return ((c == '>') && (*s == '[')) ? s : NULL; 57 } 58 } 59 return NULL; 60 } 61 62 // called if we see a '[', s is the next character, returns pointer after ']' 63 static char *is_timestamp(char *s, size_t len) { 64 while (len && (*s == ' ')) { 65 ++s; 66 --len; 67 } 68 if (!len || !isdigit(*s++)) { 69 return NULL; 70 } 71 --len; 72 bool first_period = true; 73 char c; 74 while (len && ((c = *s++))) { 75 --len; 76 if ((c == '.') && first_period) { 77 first_period = false; 78 } else if (!isdigit(c)) { 79 return ((c == ']') && !first_period && (*s == ' ')) ? s : NULL; 80 } 81 } 82 return NULL; 83 } 84 85 // Like strtok_r with "\r\n" except that we look for log signatures (regex) 86 // \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \) 87 // and split if we see a second one without a newline. 88 // We allow nuls in content, monitoring the overall length and sub-length of 89 // the discovered tokens. 90 91 #define SIGNATURE_MASK 0xF0 92 // <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature 93 #define LESS_THAN_SIG SIGNATURE_MASK 94 #define OPEN_BRACKET_SIG ((SIGNATURE_MASK << 1) & SIGNATURE_MASK) 95 // space is one more than <digit> of 9 96 #define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10)) 97 98 char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) { 99 *sublen = 0; 100 if (!*len) { 101 return NULL; 102 } 103 if (!s) { 104 if (!(s = *last)) { 105 return NULL; 106 } 107 // fixup for log signature split <, 108 // LESS_THAN_SIG + <digit> 109 if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) { 110 *s = (*s & ~SIGNATURE_MASK) + '0'; 111 *--s = '<'; 112 ++*len; 113 } 114 // fixup for log signature split [, 115 // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit> 116 if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) { 117 if (*s == OPEN_BRACKET_SPACE) { 118 *s = ' '; 119 } else { 120 *s = (*s & ~SIGNATURE_MASK) + '0'; 121 } 122 *--s = '['; 123 ++*len; 124 } 125 } 126 127 while (*len && ((*s == '\r') || (*s == '\n'))) { 128 ++s; 129 --*len; 130 } 131 132 if (!*len) { 133 *last = NULL; 134 return NULL; 135 } 136 char *peek, *tok = s; 137 138 for (;;) { 139 if (*len == 0) { 140 *last = NULL; 141 return tok; 142 } 143 char c = *s++; 144 --*len; 145 size_t adjust; 146 switch (c) { 147 case '\r': 148 case '\n': 149 s[-1] = '\0'; 150 *last = s; 151 return tok; 152 153 case '<': 154 peek = is_prio(s, *len); 155 if (!peek) { 156 break; 157 } 158 if (s != (tok + 1)) { // not first? 159 s[-1] = '\0'; 160 *s &= ~SIGNATURE_MASK; 161 *s |= LESS_THAN_SIG; // signature for '<' 162 *last = s; 163 return tok; 164 } 165 adjust = peek - s; 166 if (adjust > *len) { 167 adjust = *len; 168 } 169 *sublen += adjust; 170 *len -= adjust; 171 s = peek; 172 if ((*s == '[') && ((peek = is_timestamp(s + 1, *len - 1)))) { 173 adjust = peek - s; 174 if (adjust > *len) { 175 adjust = *len; 176 } 177 *sublen += adjust; 178 *len -= adjust; 179 s = peek; 180 } 181 break; 182 183 case '[': 184 peek = is_timestamp(s, *len); 185 if (!peek) { 186 break; 187 } 188 if (s != (tok + 1)) { // not first? 189 s[-1] = '\0'; 190 if (*s == ' ') { 191 *s = OPEN_BRACKET_SPACE; 192 } else { 193 *s &= ~SIGNATURE_MASK; 194 *s |= OPEN_BRACKET_SIG; // signature for '[' 195 } 196 *last = s; 197 return tok; 198 } 199 adjust = peek - s; 200 if (adjust > *len) { 201 adjust = *len; 202 } 203 *sublen += adjust; 204 *len -= adjust; 205 s = peek; 206 break; 207 } 208 ++*sublen; 209 } 210 // NOTREACHED 211 } 212 213 log_time LogKlog::correction = 214 (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTONIC)) 215 ? log_time::EPOCH 216 : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC)); 217 218 LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) : 219 SocketListener(fdRead, false), 220 logbuf(buf), 221 reader(reader), 222 signature(CLOCK_MONOTONIC), 223 initialized(false), 224 enableLogging(true), 225 auditd(auditd) { 226 static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n"; 227 char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4]; 228 snprintf(buffer, sizeof(buffer), klogd_message, priority_message, 229 signature.nsec()); 230 write(fdWrite, buffer, strlen(buffer)); 231 } 232 233 bool LogKlog::onDataAvailable(SocketClient *cli) { 234 if (!initialized) { 235 prctl(PR_SET_NAME, "logd.klogd"); 236 initialized = true; 237 enableLogging = false; 238 } 239 240 char buffer[LOGGER_ENTRY_MAX_PAYLOAD]; 241 size_t len = 0; 242 243 for(;;) { 244 ssize_t retval = 0; 245 if ((sizeof(buffer) - 1 - len) > 0) { 246 retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len); 247 } 248 if ((retval == 0) && (len == 0)) { 249 break; 250 } 251 if (retval < 0) { 252 return false; 253 } 254 len += retval; 255 bool full = len == (sizeof(buffer) - 1); 256 char *ep = buffer + len; 257 *ep = '\0'; 258 size_t sublen; 259 for(char *ptr = NULL, *tok = buffer; 260 ((tok = log_strntok_r(tok, &len, &ptr, &sublen))); 261 tok = NULL) { 262 if (((tok + sublen) >= ep) && (retval != 0) && full) { 263 memmove(buffer, tok, sublen); 264 len = sublen; 265 break; 266 } 267 if (*tok) { 268 log(tok, sublen); 269 } 270 } 271 } 272 273 return true; 274 } 275 276 277 void LogKlog::calculateCorrection(const log_time &monotonic, 278 const char *real_string, 279 size_t len) { 280 log_time real; 281 const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC"); 282 if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) { 283 return; 284 } 285 // kernel report UTC, log_time::strptime is localtime from calendar. 286 // Bionic and liblog strptime does not support %z or %Z to pick up 287 // timezone so we are calculating our own correction. 288 time_t now = real.tv_sec; 289 struct tm tm; 290 memset(&tm, 0, sizeof(tm)); 291 tm.tm_isdst = -1; 292 localtime_r(&now, &tm); 293 if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > (long)real.tv_sec)) { 294 real = log_time::EPOCH; 295 } else { 296 real.tv_sec += tm.tm_gmtoff; 297 } 298 if (monotonic > real) { 299 correction = log_time::EPOCH; 300 } else { 301 correction = real - monotonic; 302 } 303 } 304 305 static const char suspendStr[] = "PM: suspend entry "; 306 static const char resumeStr[] = "PM: suspend exit "; 307 static const char suspendedStr[] = "Suspended for "; 308 309 static const char *strnstr(const char *s, size_t len, const char *needle) { 310 char c; 311 312 if (!len) { 313 return NULL; 314 } 315 if ((c = *needle++) != 0) { 316 size_t needleLen = strlen(needle); 317 do { 318 do { 319 if (len <= needleLen) { 320 return NULL; 321 } 322 --len; 323 } while (*s++ != c); 324 } while (fast<memcmp>(s, needle, needleLen)); 325 s--; 326 } 327 return s; 328 } 329 330 void LogKlog::sniffTime(log_time &now, 331 const char **buf, size_t len, 332 bool reverse) { 333 const char *cp = now.strptime(*buf, "[ %s.%q]"); 334 if (cp && (cp >= &(*buf)[len])) { 335 cp = NULL; 336 } 337 if (cp) { 338 static const char healthd[] = "healthd"; 339 static const char battery[] = ": battery "; 340 341 len -= cp - *buf; 342 if (len && isspace(*cp)) { 343 ++cp; 344 --len; 345 } 346 *buf = cp; 347 348 if (isMonotonic()) { 349 return; 350 } 351 352 const char *b; 353 if (((b = strnstr(cp, len, suspendStr))) 354 && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { 355 len -= b - cp; 356 calculateCorrection(now, b, len); 357 } else if (((b = strnstr(cp, len, resumeStr))) 358 && ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) { 359 len -= b - cp; 360 calculateCorrection(now, b, len); 361 } else if (((b = strnstr(cp, len, healthd))) 362 && ((size_t)((b += sizeof(healthd) - 1) - cp) < len) 363 && ((b = strnstr(b, len -= b - cp, battery))) 364 && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) { 365 // NB: healthd is roughly 150us late, so we use it instead to 366 // trigger a check for ntp-induced or hardware clock drift. 367 log_time real(CLOCK_REALTIME); 368 log_time mono(CLOCK_MONOTONIC); 369 correction = (real < mono) ? log_time::EPOCH : (real - mono); 370 } else if (((b = strnstr(cp, len, suspendedStr))) 371 && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { 372 len -= b - cp; 373 log_time real; 374 char *endp; 375 real.tv_sec = strtol(b, &endp, 10); 376 if ((*endp == '.') && ((size_t)(endp - b) < len)) { 377 unsigned long multiplier = NS_PER_SEC; 378 real.tv_nsec = 0; 379 len -= endp - b; 380 while (--len && isdigit(*++endp) && (multiplier /= 10)) { 381 real.tv_nsec += (*endp - '0') * multiplier; 382 } 383 if (reverse) { 384 if (real > correction) { 385 correction = log_time::EPOCH; 386 } else { 387 correction -= real; 388 } 389 } else { 390 correction += real; 391 } 392 } 393 } 394 395 convertMonotonicToReal(now); 396 } else { 397 if (isMonotonic()) { 398 now = log_time(CLOCK_MONOTONIC); 399 } else { 400 now = log_time(CLOCK_REALTIME); 401 } 402 } 403 } 404 405 pid_t LogKlog::sniffPid(const char **buf, size_t len) { 406 const char *cp = *buf; 407 // HTC kernels with modified printk "c0 1648 " 408 if ((len > 9) && 409 (cp[0] == 'c') && 410 isdigit(cp[1]) && 411 (isdigit(cp[2]) || (cp[2] == ' ')) && 412 (cp[3] == ' ')) { 413 bool gotDigit = false; 414 int i; 415 for (i = 4; i < 9; ++i) { 416 if (isdigit(cp[i])) { 417 gotDigit = true; 418 } else if (gotDigit || (cp[i] != ' ')) { 419 break; 420 } 421 } 422 if ((i == 9) && (cp[i] == ' ')) { 423 int pid = 0; 424 char dummy; 425 if (sscanf(cp + 4, "%d%c", &pid, &dummy) == 2) { 426 *buf = cp + 10; // skip-it-all 427 return pid; 428 } 429 } 430 } 431 while (len) { 432 // Mediatek kernels with modified printk 433 if (*cp == '[') { 434 int pid = 0; 435 char dummy; 436 if (sscanf(cp, "[%d:%*[a-z_./0-9:A-Z]]%c", &pid, &dummy) == 2) { 437 return pid; 438 } 439 break; // Only the first one 440 } 441 ++cp; 442 --len; 443 } 444 return 0; 445 } 446 447 // kernel log prefix, convert to a kernel log priority number 448 static int parseKernelPrio(const char **buf, size_t len) { 449 int pri = LOG_USER | LOG_INFO; 450 const char *cp = *buf; 451 if (len && (*cp == '<')) { 452 pri = 0; 453 while(--len && isdigit(*++cp)) { 454 pri = (pri * 10) + *cp - '0'; 455 } 456 if (len && (*cp == '>')) { 457 ++cp; 458 } else { 459 cp = *buf; 460 pri = LOG_USER | LOG_INFO; 461 } 462 *buf = cp; 463 } 464 return pri; 465 } 466 467 // Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a 468 // compensated start time. 469 void LogKlog::synchronize(const char *buf, size_t len) { 470 const char *cp = strnstr(buf, len, suspendStr); 471 if (!cp) { 472 cp = strnstr(buf, len, resumeStr); 473 if (!cp) { 474 return; 475 } 476 } else { 477 const char *rp = strnstr(buf, len, resumeStr); 478 if (rp && (rp < cp)) { 479 cp = rp; 480 } 481 } 482 483 do { 484 --cp; 485 } while ((cp > buf) && (*cp != '\n')); 486 if (*cp == '\n') { 487 ++cp; 488 } 489 parseKernelPrio(&cp, len - (cp - buf)); 490 491 log_time now; 492 sniffTime(now, &cp, len - (cp - buf), true); 493 494 const char *suspended = strnstr(buf, len, suspendedStr); 495 if (!suspended || (suspended > cp)) { 496 return; 497 } 498 cp = suspended; 499 500 do { 501 --cp; 502 } while ((cp > buf) && (*cp != '\n')); 503 if (*cp == '\n') { 504 ++cp; 505 } 506 parseKernelPrio(&cp, len - (cp - buf)); 507 508 sniffTime(now, &cp, len - (cp - buf), true); 509 } 510 511 // Convert kernel log priority number into an Android Logger priority number 512 static int convertKernelPrioToAndroidPrio(int pri) { 513 switch(pri & LOG_PRIMASK) { 514 case LOG_EMERG: 515 // FALLTHRU 516 case LOG_ALERT: 517 // FALLTHRU 518 case LOG_CRIT: 519 return ANDROID_LOG_FATAL; 520 521 case LOG_ERR: 522 return ANDROID_LOG_ERROR; 523 524 case LOG_WARNING: 525 return ANDROID_LOG_WARN; 526 527 default: 528 // FALLTHRU 529 case LOG_NOTICE: 530 // FALLTHRU 531 case LOG_INFO: 532 break; 533 534 case LOG_DEBUG: 535 return ANDROID_LOG_DEBUG; 536 } 537 538 return ANDROID_LOG_INFO; 539 } 540 541 static const char *strnrchr(const char *s, size_t len, char c) { 542 const char *save = NULL; 543 for (;len; ++s, len--) { 544 if (*s == c) { 545 save = s; 546 } 547 } 548 return save; 549 } 550 551 // 552 // log a message into the kernel log buffer 553 // 554 // Filter rules to parse <PRI> <TIME> <tag> and <message> in order for 555 // them to appear correct in the logcat output: 556 // 557 // LOG_KERN (0): 558 // <PRI>[<TIME>] <tag> ":" <message> 559 // <PRI>[<TIME>] <tag> <tag> ":" <message> 560 // <PRI>[<TIME>] <tag> <tag>_work ":" <message> 561 // <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message> 562 // <PRI>[<TIME>] <tag> '<tag><num>' ":" <message> 563 // <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message> 564 // (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message> 565 // <PRI>[<TIME>] "[INFO]"<tag> : <message> 566 // <PRI>[<TIME>] "------------[ cut here ]------------" (?) 567 // <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---" (?) 568 // LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS 569 // LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP: 570 // <PRI+TAG>[<TIME>] (see sys/syslog.h) 571 // Observe: 572 // Minimum tag length = 3 NB: drops things like r5:c00bbadf, but allow PM: 573 // Maximum tag words = 2 574 // Maximum tag length = 16 NB: we are thinking of how ugly logcat can get. 575 // Not a Tag if there is no message content. 576 // leading additional spaces means no tag, inherit last tag. 577 // Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:" 578 // Drop: 579 // empty messages 580 // messages with ' audit(' in them if auditd is running 581 // logd.klogd: 582 // return -1 if message logd.klogd: <signature> 583 // 584 int LogKlog::log(const char *buf, size_t len) { 585 if (auditd && strnstr(buf, len, " audit(")) { 586 return 0; 587 } 588 589 const char *p = buf; 590 int pri = parseKernelPrio(&p, len); 591 592 log_time now; 593 sniffTime(now, &p, len - (p - buf), false); 594 595 // sniff for start marker 596 const char klogd_message[] = "logd.klogd: "; 597 const char *start = strnstr(p, len - (p - buf), klogd_message); 598 if (start) { 599 uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10); 600 if (sig == signature.nsec()) { 601 if (initialized) { 602 enableLogging = true; 603 } else { 604 enableLogging = false; 605 } 606 return -1; 607 } 608 return 0; 609 } 610 611 if (!enableLogging) { 612 return 0; 613 } 614 615 // Parse pid, tid and uid 616 const pid_t pid = sniffPid(&p, len - (p - buf)); 617 const pid_t tid = pid; 618 uid_t uid = AID_ROOT; 619 if (pid) { 620 logbuf->lock(); 621 uid = logbuf->pidToUid(pid); 622 logbuf->unlock(); 623 } 624 625 // Parse (rules at top) to pull out a tag from the incoming kernel message. 626 // Some may view the following as an ugly heuristic, the desire is to 627 // beautify the kernel logs into an Android Logging format; the goal is 628 // admirable but costly. 629 while ((p < &buf[len]) && (isspace(*p) || !*p)) { 630 ++p; 631 } 632 if (p >= &buf[len]) { // timestamp, no content 633 return 0; 634 } 635 start = p; 636 const char *tag = ""; 637 const char *etag = tag; 638 size_t taglen = len - (p - buf); 639 const char *bt = p; 640 641 static const char infoBrace[] = "[INFO]"; 642 static const size_t infoBraceLen = strlen(infoBrace); 643 if ((taglen >= infoBraceLen) && !fast<strncmp>(p, infoBrace, infoBraceLen)) { 644 // <PRI>[<TIME>] "[INFO]"<tag> ":" message 645 bt = p + infoBraceLen; 646 taglen -= infoBraceLen; 647 } 648 649 const char *et; 650 for (et = bt; taglen && *et && (*et != ':') && !isspace(*et); ++et, --taglen) { 651 // skip ':' within [ ... ] 652 if (*et == '[') { 653 while (taglen && *et && *et != ']') { 654 ++et; 655 --taglen; 656 } 657 if (!taglen) { 658 break; 659 } 660 } 661 } 662 const char *cp; 663 for (cp = et; taglen && isspace(*cp); ++cp, --taglen); 664 665 // Validate tag 666 size_t size = et - bt; 667 if (taglen && size) { 668 if (*cp == ':') { 669 // ToDo: handle case insensitive colon separated logging stutter: 670 // <tag> : <tag>: ... 671 672 // One Word 673 tag = bt; 674 etag = et; 675 p = cp + 1; 676 } else if ((taglen > size) && (tolower(*bt) == tolower(*cp))) { 677 // clean up any tag stutter 678 if (!fast<strncasecmp>(bt + 1, cp + 1, size - 1)) { // no match 679 // <PRI>[<TIME>] <tag> <tag> : message 680 // <PRI>[<TIME>] <tag> <tag>: message 681 // <PRI>[<TIME>] <tag> '<tag>.<num>' : message 682 // <PRI>[<TIME>] <tag> '<tag><num>' : message 683 // <PRI>[<TIME>] <tag> '<tag><stuff>' : message 684 const char *b = cp; 685 cp += size; 686 taglen -= size; 687 while (--taglen && !isspace(*++cp) && (*cp != ':')); 688 const char *e; 689 for (e = cp; taglen && isspace(*cp); ++cp, --taglen); 690 if (taglen && (*cp == ':')) { 691 tag = b; 692 etag = e; 693 p = cp + 1; 694 } 695 } else { 696 // what about <PRI>[<TIME>] <tag>_host '<tag><stuff>' : message 697 static const char host[] = "_host"; 698 static const size_t hostlen = strlen(host); 699 if ((size > hostlen) && 700 !fast<strncmp>(bt + size - hostlen, host, hostlen) && 701 !fast<strncmp>(bt + 1, cp + 1, size - hostlen - 1)) { 702 const char *b = cp; 703 cp += size - hostlen; 704 taglen -= size - hostlen; 705 if (*cp == '.') { 706 while (--taglen && !isspace(*++cp) && (*cp != ':')); 707 const char *e; 708 for (e = cp; taglen && isspace(*cp); ++cp, --taglen); 709 if (taglen && (*cp == ':')) { 710 tag = b; 711 etag = e; 712 p = cp + 1; 713 } 714 } 715 } else { 716 goto twoWord; 717 } 718 } 719 } else { 720 // <PRI>[<TIME>] <tag> <stuff>' : message 721 twoWord: while (--taglen && !isspace(*++cp) && (*cp != ':')); 722 const char *e; 723 for (e = cp; taglen && isspace(*cp); ++cp, --taglen); 724 // Two words 725 if (taglen && (*cp == ':')) { 726 tag = bt; 727 etag = e; 728 p = cp + 1; 729 } 730 } 731 } // else no tag 732 733 static const char cpu[] = "CPU"; 734 static const size_t cpuLen = strlen(cpu); 735 static const char warning[] = "WARNING"; 736 static const size_t warningLen = strlen(warning); 737 static const char error[] = "ERROR"; 738 static const size_t errorLen = strlen(error); 739 static const char info[] = "INFO"; 740 static const size_t infoLen = strlen(info); 741 742 size = etag - tag; 743 if ((size <= 1) 744 // register names like x9 745 || ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1]))) 746 // register names like x18 but not driver names like en0 747 || ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2]))) 748 // blacklist 749 || ((size == cpuLen) && !fast<strncmp>(tag, cpu, cpuLen)) 750 || ((size == warningLen) && !fast<strncasecmp>(tag, warning, warningLen)) 751 || ((size == errorLen) && !fast<strncasecmp>(tag, error, errorLen)) 752 || ((size == infoLen) && !fast<strncasecmp>(tag, info, infoLen))) { 753 p = start; 754 etag = tag = ""; 755 } 756 757 // Suppress additional stutter in tag: 758 // eg: [143:healthd]healthd -> [143:healthd] 759 taglen = etag - tag; 760 // Mediatek-special printk induced stutter 761 const char *mp = strnrchr(tag, ']', taglen); 762 if (mp && (++mp < etag)) { 763 size_t s = etag - mp; 764 if (((s + s) < taglen) && !fast<memcmp>(mp, mp - 1 - s, s)) { 765 taglen = mp - tag; 766 } 767 } 768 // Deal with sloppy and simplistic harmless p = cp + 1 etc above. 769 if (len < (size_t)(p - buf)) { 770 p = &buf[len]; 771 } 772 // skip leading space 773 while ((p < &buf[len]) && (isspace(*p) || !*p)) { 774 ++p; 775 } 776 // truncate trailing space or nuls 777 size_t b = len - (p - buf); 778 while (b && (isspace(p[b-1]) || !p[b-1])) { 779 --b; 780 } 781 // trick ... allow tag with empty content to be logged. log() drops empty 782 if (!b && taglen) { 783 p = " "; 784 b = 1; 785 } 786 // paranoid sanity check, can not happen ... 787 if (b > LOGGER_ENTRY_MAX_PAYLOAD) { 788 b = LOGGER_ENTRY_MAX_PAYLOAD; 789 } 790 if (taglen > LOGGER_ENTRY_MAX_PAYLOAD) { 791 taglen = LOGGER_ENTRY_MAX_PAYLOAD; 792 } 793 // calculate buffer copy requirements 794 size_t n = 1 + taglen + 1 + b + 1; 795 // paranoid sanity check, first two just can not happen ... 796 if ((taglen > n) || (b > n) || (n > USHRT_MAX)) { 797 return -EINVAL; 798 } 799 800 // Careful. 801 // We are using the stack to house the log buffer for speed reasons. 802 // If we malloc'd this buffer, we could get away without n's USHRT_MAX 803 // test above, but we would then required a max(n, USHRT_MAX) as 804 // truncating length argument to logbuf->log() below. Gain is protection 805 // of stack sanity and speedup, loss is truncated long-line content. 806 char newstr[n]; 807 char *np = newstr; 808 809 // Convert priority into single-byte Android logger priority 810 *np = convertKernelPrioToAndroidPrio(pri); 811 ++np; 812 813 // Copy parsed tag following priority 814 memcpy(np, tag, taglen); 815 np += taglen; 816 *np = '\0'; 817 ++np; 818 819 // Copy main message to the remainder 820 memcpy(np, p, b); 821 np[b] = '\0'; 822 823 if (!isMonotonic()) { 824 // Watch out for singular race conditions with timezone causing near 825 // integer quarter-hour jumps in the time and compensate accordingly. 826 // Entries will be temporal within near_seconds * 2. b/21868540 827 static uint32_t vote_time[3]; 828 vote_time[2] = vote_time[1]; 829 vote_time[1] = vote_time[0]; 830 vote_time[0] = now.tv_sec; 831 832 if (vote_time[1] && vote_time[2]) { 833 static const unsigned near_seconds = 10; 834 static const unsigned timezones_seconds = 900; 835 int diff0 = (vote_time[0] - vote_time[1]) / near_seconds; 836 unsigned abs0 = (diff0 < 0) ? -diff0 : diff0; 837 int diff1 = (vote_time[1] - vote_time[2]) / near_seconds; 838 unsigned abs1 = (diff1 < 0) ? -diff1 : diff1; 839 if ((abs1 <= 1) && // last two were in agreement on timezone 840 ((abs0 + 1) % (timezones_seconds / near_seconds)) <= 2) { 841 abs0 = (abs0 + 1) / (timezones_seconds / near_seconds) * 842 timezones_seconds; 843 now.tv_sec -= (diff0 < 0) ? -abs0 : abs0; 844 } 845 } 846 } 847 848 // Log message 849 int rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr, 850 (unsigned short) n); 851 852 // notify readers 853 if (!rc) { 854 reader->notifyNewLog(); 855 } 856 857 return rc; 858 } 859
