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 <sys/prctl.h> 24 #include <sys/uio.h> 25 #include <syslog.h> 26 27 #include <log/logger.h> 28 29 #include "LogKlog.h" 30 31 #define KMSG_PRIORITY(PRI) \ 32 '<', \ 33 '0' + (LOG_SYSLOG | (PRI)) / 10, \ 34 '0' + (LOG_SYSLOG | (PRI)) % 10, \ 35 '>' 36 37 static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' }; 38 39 // Parsing is hard 40 41 // called if we see a '<', s is the next character, returns pointer after '>' 42 static char *is_prio(char *s) { 43 if (!isdigit(*s++)) { 44 return NULL; 45 } 46 char c; 47 while ((c = *s++)) { 48 if (!isdigit(c)) { 49 return (c == '>') ? s : NULL; 50 } 51 } 52 return NULL; 53 } 54 55 // called if we see a '[', s is the next character, returns pointer after ']' 56 static char *is_timestamp(char *s) { 57 while (*s == ' ') { 58 ++s; 59 } 60 if (!isdigit(*s++)) { 61 return NULL; 62 } 63 bool first_period = true; 64 char c; 65 while ((c = *s++)) { 66 if ((c == '.') && first_period) { 67 first_period = false; 68 } else if (!isdigit(c)) { 69 return ((c == ']') && !first_period && (*s == ' ')) ? s : NULL; 70 } 71 } 72 return NULL; 73 } 74 75 // Like strtok_r with "\r\n" except that we look for log signatures (regex) 76 // \(\(<[0-9]+>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \) 77 // and split if we see a second one without a newline. 78 79 #define SIGNATURE_MASK 0xF0 80 // <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature 81 #define LESS_THAN_SIG SIGNATURE_MASK 82 #define OPEN_BRACKET_SIG ((SIGNATURE_MASK << 1) & SIGNATURE_MASK) 83 // space is one more than <digit> of 9 84 #define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10)) 85 86 char *log_strtok_r(char *s, char **last) { 87 if (!s) { 88 if (!(s = *last)) { 89 return NULL; 90 } 91 // fixup for log signature split <, 92 // LESS_THAN_SIG + <digit> 93 if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) { 94 *s = (*s & ~SIGNATURE_MASK) + '0'; 95 *--s = '<'; 96 } 97 // fixup for log signature split [, 98 // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit> 99 if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) { 100 if (*s == OPEN_BRACKET_SPACE) { 101 *s = ' '; 102 } else { 103 *s = (*s & ~SIGNATURE_MASK) + '0'; 104 } 105 *--s = '['; 106 } 107 } 108 109 s += strspn(s, "\r\n"); 110 111 if (!*s) { // no non-delimiter characters 112 *last = NULL; 113 return NULL; 114 } 115 char *peek, *tok = s; 116 117 for (;;) { 118 char c = *s++; 119 switch (c) { 120 case '\0': 121 *last = NULL; 122 return tok; 123 124 case '\r': 125 case '\n': 126 s[-1] = '\0'; 127 *last = s; 128 return tok; 129 130 case '<': 131 peek = is_prio(s); 132 if (!peek) { 133 break; 134 } 135 if (s != (tok + 1)) { // not first? 136 s[-1] = '\0'; 137 *s &= ~SIGNATURE_MASK; 138 *s |= LESS_THAN_SIG; // signature for '<' 139 *last = s; 140 return tok; 141 } 142 s = peek; 143 if ((*s == '[') && ((peek = is_timestamp(s + 1)))) { 144 s = peek; 145 } 146 break; 147 148 case '[': 149 peek = is_timestamp(s); 150 if (!peek) { 151 break; 152 } 153 if (s != (tok + 1)) { // not first? 154 s[-1] = '\0'; 155 if (*s == ' ') { 156 *s = OPEN_BRACKET_SPACE; 157 } else { 158 *s &= ~SIGNATURE_MASK; 159 *s |= OPEN_BRACKET_SIG; // signature for '[' 160 } 161 *last = s; 162 return tok; 163 } 164 s = peek; 165 break; 166 } 167 } 168 /* NOTREACHED */ 169 } 170 171 log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC); 172 173 LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) : 174 SocketListener(fdRead, false), 175 logbuf(buf), 176 reader(reader), 177 signature(CLOCK_MONOTONIC), 178 fdWrite(fdWrite), 179 fdRead(fdRead), 180 initialized(false), 181 enableLogging(true), 182 auditd(auditd) { 183 static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n"; 184 char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4]; 185 snprintf(buffer, sizeof(buffer), klogd_message, priority_message, 186 signature.nsec()); 187 write(fdWrite, buffer, strlen(buffer)); 188 } 189 190 bool LogKlog::onDataAvailable(SocketClient *cli) { 191 if (!initialized) { 192 prctl(PR_SET_NAME, "logd.klogd"); 193 initialized = true; 194 enableLogging = false; 195 } 196 197 char buffer[LOGGER_ENTRY_MAX_PAYLOAD]; 198 size_t len = 0; 199 200 for(;;) { 201 ssize_t retval = 0; 202 if ((sizeof(buffer) - 1 - len) > 0) { 203 retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len); 204 } 205 if ((retval == 0) && (len == 0)) { 206 break; 207 } 208 if (retval < 0) { 209 return false; 210 } 211 len += retval; 212 bool full = len == (sizeof(buffer) - 1); 213 char *ep = buffer + len; 214 *ep = '\0'; 215 len = 0; 216 for(char *ptr = NULL, *tok = buffer; 217 ((tok = log_strtok_r(tok, &ptr))); 218 tok = NULL) { 219 if (((tok + strlen(tok)) == ep) && (retval != 0) && full) { 220 len = strlen(tok); 221 memmove(buffer, tok, len); 222 break; 223 } 224 if (*tok) { 225 log(tok); 226 } 227 } 228 } 229 230 return true; 231 } 232 233 234 void LogKlog::calculateCorrection(const log_time &monotonic, 235 const char *real_string) { 236 log_time real; 237 if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) { 238 return; 239 } 240 // kernel report UTC, log_time::strptime is localtime from calendar. 241 // Bionic and liblog strptime does not support %z or %Z to pick up 242 // timezone so we are calculating our own correction. 243 time_t now = real.tv_sec; 244 struct tm tm; 245 memset(&tm, 0, sizeof(tm)); 246 tm.tm_isdst = -1; 247 localtime_r(&now, &tm); 248 real.tv_sec += tm.tm_gmtoff; 249 correction = real - monotonic; 250 } 251 252 void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { 253 const char *cp; 254 if ((cp = now.strptime(*buf, "[ %s.%q]"))) { 255 static const char suspend[] = "PM: suspend entry "; 256 static const char resume[] = "PM: suspend exit "; 257 static const char suspended[] = "Suspended for "; 258 259 if (isspace(*cp)) { 260 ++cp; 261 } 262 if (!strncmp(cp, suspend, sizeof(suspend) - 1)) { 263 calculateCorrection(now, cp + sizeof(suspend) - 1); 264 } else if (!strncmp(cp, resume, sizeof(resume) - 1)) { 265 calculateCorrection(now, cp + sizeof(resume) - 1); 266 } else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) { 267 log_time real; 268 char *endp; 269 real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10); 270 if (*endp == '.') { 271 real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L; 272 if (reverse) { 273 correction -= real; 274 } else { 275 correction += real; 276 } 277 } 278 } 279 280 convertMonotonicToReal(now); 281 *buf = cp; 282 } else { 283 now = log_time(CLOCK_REALTIME); 284 } 285 } 286 287 // Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a 288 // compensated start time. 289 void LogKlog::synchronize(const char *buf) { 290 const char *cp = strstr(buf, "] PM: suspend e"); 291 if (!cp) { 292 return; 293 } 294 295 do { 296 --cp; 297 } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.'))); 298 299 log_time now; 300 sniffTime(now, &cp, true); 301 302 char *suspended = strstr(buf, "] Suspended for "); 303 if (!suspended || (suspended > cp)) { 304 return; 305 } 306 cp = suspended; 307 308 do { 309 --cp; 310 } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.'))); 311 312 sniffTime(now, &cp, true); 313 } 314 315 // kernel log prefix, convert to a kernel log priority number 316 static int parseKernelPrio(const char **buf) { 317 int pri = LOG_USER | LOG_INFO; 318 const char *cp = *buf; 319 if (*cp == '<') { 320 pri = 0; 321 while(isdigit(*++cp)) { 322 pri = (pri * 10) + *cp - '0'; 323 } 324 if (*cp == '>') { 325 ++cp; 326 } else { 327 cp = *buf; 328 pri = LOG_USER | LOG_INFO; 329 } 330 *buf = cp; 331 } 332 return pri; 333 } 334 335 // Convert kernel log priority number into an Android Logger priority number 336 static int convertKernelPrioToAndroidPrio(int pri) { 337 switch(pri & LOG_PRIMASK) { 338 case LOG_EMERG: 339 // FALLTHRU 340 case LOG_ALERT: 341 // FALLTHRU 342 case LOG_CRIT: 343 return ANDROID_LOG_FATAL; 344 345 case LOG_ERR: 346 return ANDROID_LOG_ERROR; 347 348 case LOG_WARNING: 349 return ANDROID_LOG_WARN; 350 351 default: 352 // FALLTHRU 353 case LOG_NOTICE: 354 // FALLTHRU 355 case LOG_INFO: 356 break; 357 358 case LOG_DEBUG: 359 return ANDROID_LOG_DEBUG; 360 } 361 362 return ANDROID_LOG_INFO; 363 } 364 365 // 366 // log a message into the kernel log buffer 367 // 368 // Filter rules to parse <PRI> <TIME> <tag> and <message> in order for 369 // them to appear correct in the logcat output: 370 // 371 // LOG_KERN (0): 372 // <PRI>[<TIME>] <tag> ":" <message> 373 // <PRI>[<TIME>] <tag> <tag> ":" <message> 374 // <PRI>[<TIME>] <tag> <tag>_work ":" <message> 375 // <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message> 376 // <PRI>[<TIME>] <tag> '<tag><num>' ":" <message> 377 // <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message> 378 // (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message> 379 // <PRI>[<TIME>] "[INFO]"<tag> : <message> 380 // <PRI>[<TIME>] "------------[ cut here ]------------" (?) 381 // <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---" (?) 382 // LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS 383 // LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP: 384 // <PRI+TAG>[<TIME>] (see sys/syslog.h) 385 // Observe: 386 // Minimum tag length = 3 NB: drops things like r5:c00bbadf, but allow PM: 387 // Maximum tag words = 2 388 // Maximum tag length = 16 NB: we are thinking of how ugly logcat can get. 389 // Not a Tag if there is no message content. 390 // leading additional spaces means no tag, inherit last tag. 391 // Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:" 392 // Drop: 393 // empty messages 394 // messages with ' audit(' in them if auditd is running 395 // logd.klogd: 396 // return -1 if message logd.klogd: <signature> 397 // 398 int LogKlog::log(const char *buf) { 399 if (auditd && strstr(buf, " audit(")) { 400 return 0; 401 } 402 403 int pri = parseKernelPrio(&buf); 404 405 log_time now; 406 sniffTime(now, &buf, false); 407 408 // sniff for start marker 409 const char klogd_message[] = "logd.klogd: "; 410 if (!strncmp(buf, klogd_message, sizeof(klogd_message) - 1)) { 411 char *endp; 412 uint64_t sig = strtoll(buf + sizeof(klogd_message) - 1, &endp, 10); 413 if (sig == signature.nsec()) { 414 if (initialized) { 415 enableLogging = true; 416 } else { 417 enableLogging = false; 418 } 419 return -1; 420 } 421 return 0; 422 } 423 424 if (!enableLogging) { 425 return 0; 426 } 427 428 // Parse pid, tid and uid (not possible) 429 const pid_t pid = 0; 430 const pid_t tid = 0; 431 const uid_t uid = 0; 432 433 // Parse (rules at top) to pull out a tag from the incoming kernel message. 434 // Some may view the following as an ugly heuristic, the desire is to 435 // beautify the kernel logs into an Android Logging format; the goal is 436 // admirable but costly. 437 while (isspace(*buf)) { 438 ++buf; 439 } 440 if (!*buf) { 441 return 0; 442 } 443 const char *start = buf; 444 const char *tag = ""; 445 const char *etag = tag; 446 if (!isspace(*buf)) { 447 const char *bt, *et, *cp; 448 449 bt = buf; 450 if (!strncmp(buf, "[INFO]", 6)) { 451 // <PRI>[<TIME>] "[INFO]"<tag> ":" message 452 bt = buf + 6; 453 } 454 for(et = bt; *et && (*et != ':') && !isspace(*et); ++et); 455 for(cp = et; isspace(*cp); ++cp); 456 size_t size; 457 458 if (*cp == ':') { 459 // One Word 460 tag = bt; 461 etag = et; 462 buf = cp + 1; 463 } else { 464 size = et - bt; 465 if (strncmp(bt, cp, size)) { 466 // <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message 467 if (!strncmp(bt + size - 5, "_host", 5) 468 && !strncmp(bt, cp, size - 5)) { 469 const char *b = cp; 470 cp += size - 5; 471 if (*cp == '.') { 472 while (!isspace(*++cp) && (*cp != ':')); 473 const char *e; 474 for(e = cp; isspace(*cp); ++cp); 475 if (*cp == ':') { 476 tag = b; 477 etag = e; 478 buf = cp + 1; 479 } 480 } 481 } else { 482 while (!isspace(*++cp) && (*cp != ':')); 483 const char *e; 484 for(e = cp; isspace(*cp); ++cp); 485 // Two words 486 if (*cp == ':') { 487 tag = bt; 488 etag = e; 489 buf = cp + 1; 490 } 491 } 492 } else if (isspace(cp[size])) { 493 const char *b = cp; 494 cp += size; 495 while (isspace(*++cp)); 496 // <PRI>[<TIME>] <tag> <tag> : message 497 if (*cp == ':') { 498 tag = bt; 499 etag = et; 500 buf = cp + 1; 501 } 502 } else if (cp[size] == ':') { 503 // <PRI>[<TIME>] <tag> <tag> : message 504 tag = bt; 505 etag = et; 506 buf = cp + size + 1; 507 } else if ((cp[size] == '.') || isdigit(cp[size])) { 508 // <PRI>[<TIME>] <tag> '<tag>.<num>' : message 509 // <PRI>[<TIME>] <tag> '<tag><num>' : message 510 const char *b = cp; 511 cp += size; 512 while (!isspace(*++cp) && (*cp != ':')); 513 const char *e = cp; 514 while (isspace(*cp)) { 515 ++cp; 516 } 517 if (*cp == ':') { 518 tag = b; 519 etag = e; 520 buf = cp + 1; 521 } 522 } else { 523 while (!isspace(*++cp) && (*cp != ':')); 524 const char *e = cp; 525 while (isspace(*cp)) { 526 ++cp; 527 } 528 // Two words 529 if (*cp == ':') { 530 tag = bt; 531 etag = e; 532 buf = cp + 1; 533 } 534 } 535 } 536 size = etag - tag; 537 if ((size <= 1) 538 || ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1]))) 539 || ((size == 3) && !strncmp(tag, "CPU", 3)) 540 || ((size == 7) && !strncmp(tag, "WARNING", 7)) 541 || ((size == 5) && !strncmp(tag, "ERROR", 5)) 542 || ((size == 4) && !strncmp(tag, "INFO", 4))) { 543 buf = start; 544 etag = tag = ""; 545 } 546 } 547 size_t l = etag - tag; 548 // skip leading space 549 while (isspace(*buf)) { 550 ++buf; 551 } 552 // truncate trailing space 553 size_t b = strlen(buf); 554 while (b && isspace(buf[b-1])) { 555 --b; 556 } 557 // trick ... allow tag with empty content to be logged. log() drops empty 558 if (!b && l) { 559 buf = " "; 560 b = 1; 561 } 562 size_t n = 1 + l + 1 + b + 1; 563 564 // Allocate a buffer to hold the interpreted log message 565 int rc = n; 566 char *newstr = reinterpret_cast<char *>(malloc(n)); 567 if (!newstr) { 568 rc = -ENOMEM; 569 return rc; 570 } 571 char *np = newstr; 572 573 // Convert priority into single-byte Android logger priority 574 *np = convertKernelPrioToAndroidPrio(pri); 575 ++np; 576 577 // Copy parsed tag following priority 578 strncpy(np, tag, l); 579 np += l; 580 *np = '\0'; 581 ++np; 582 583 // Copy main message to the remainder 584 strncpy(np, buf, b); 585 np[b] = '\0'; 586 587 // Log message 588 rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr, 589 (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX); 590 free(newstr); 591 592 // notify readers 593 if (!rc) { 594 reader->notifyNewLog(); 595 } 596 597 return rc; 598 } 599
