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