/* * Copyright (C) 2014 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include #include #include #include #include #include #include #include #include #include #include "LogKlog.h" #define KMSG_PRIORITY(PRI) \ '<', \ '0' + (LOG_SYSLOG | (PRI)) / 10, \ '0' + (LOG_SYSLOG | (PRI)) % 10, \ '>' static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' }; // Parsing is hard // called if we see a '<', s is the next character, returns pointer after '>' static char *is_prio(char *s) { if (!isdigit(*s++)) { return NULL; } char c; while ((c = *s++)) { if (!isdigit(c) && (c == '>')) { return s; } } return NULL; } // called if we see a '[', s is the next character, returns pointer after ']' static char *is_timestamp(char *s) { while (*s == ' ') { ++s; } if (!isdigit(*s++)) { return NULL; } bool first_period = true; char c; while ((c = *s++)) { if ((c == '.') && first_period) { first_period = false; continue; } if (!isdigit(c) && (c == ']')) { return s; } } return NULL; } // Like strtok_r with "\r\n" except that we look for log signatures (regex) // \(\(<[0-9]+>\)\([[] *[0-9]+[]]\)\{0,1\}\|[[] *[0-9]+[]]\) // and split if we see a second one without a newline. #define SIGNATURE_MASK 0xF0 // following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature #define LESS_THAN_SIG SIGNATURE_MASK #define OPEN_BRACKET_SIG ((SIGNATURE_MASK << 1) & SIGNATURE_MASK) // space is one more than of 9 #define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10)) char *log_strtok_r(char *s, char **last) { if (!s) { if (!(s = *last)) { return NULL; } // fixup for log signature split <, // LESS_THAN_SIG + if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) { *s = (*s & ~SIGNATURE_MASK) + '0'; *--s = '<'; } // fixup for log signature split [, // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) { if (*s == OPEN_BRACKET_SPACE) { *s = ' '; } else { *s = (*s & ~SIGNATURE_MASK) + '0'; } *--s = '['; } } s += strspn(s, "\r\n"); if (!*s) { // no non-delimiter characters *last = NULL; return NULL; } char *peek, *tok = s; for (;;) { char c = *s++; switch (c) { case '\0': *last = NULL; return tok; case '\r': case '\n': s[-1] = '\0'; *last = s; return tok; case '<': peek = is_prio(s); if (!peek) { break; } if (s != (tok + 1)) { // not first? s[-1] = '\0'; *s &= ~SIGNATURE_MASK; *s |= LESS_THAN_SIG; // signature for '<' *last = s; return tok; } s = peek; if ((*s == '[') && ((peek = is_timestamp(s + 1)))) { s = peek; } break; case '[': peek = is_timestamp(s); if (!peek) { break; } if (s != (tok + 1)) { // not first? s[-1] = '\0'; if (*s == ' ') { *s = OPEN_BRACKET_SPACE; } else { *s &= ~SIGNATURE_MASK; *s |= OPEN_BRACKET_SIG; // signature for '[' } *last = s; return tok; } s = peek; break; } } /* NOTREACHED */ } log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC); LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) : SocketListener(fdRead, false), logbuf(buf), reader(reader), signature(CLOCK_MONOTONIC), fdWrite(fdWrite), fdRead(fdRead), initialized(false), enableLogging(true), auditd(auditd) { static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n"; char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4]; snprintf(buffer, sizeof(buffer), klogd_message, priority_message, signature.nsec()); write(fdWrite, buffer, strlen(buffer)); } bool LogKlog::onDataAvailable(SocketClient *cli) { if (!initialized) { prctl(PR_SET_NAME, "logd.klogd"); initialized = true; enableLogging = false; } char buffer[LOGGER_ENTRY_MAX_PAYLOAD]; size_t len = 0; for(;;) { ssize_t retval = 0; if ((sizeof(buffer) - 1 - len) > 0) { retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len); } if ((retval == 0) && (len == 0)) { break; } if (retval < 0) { return false; } len += retval; bool full = len == (sizeof(buffer) - 1); char *ep = buffer + len; *ep = '\0'; len = 0; for(char *ptr = NULL, *tok = buffer; ((tok = log_strtok_r(tok, &ptr))); tok = NULL) { if (((tok + strlen(tok)) == ep) && (retval != 0) && full) { len = strlen(tok); memmove(buffer, tok, len); break; } if (*tok) { log(tok); } } } return true; } void LogKlog::calculateCorrection(const log_time &monotonic, const char *real_string) { log_time real; if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) { return; } // kernel report UTC, log_time::strptime is localtime from calendar. // Bionic and liblog strptime does not support %z or %Z to pick up // timezone so we are calculating our own correction. time_t now = real.tv_sec; struct tm tm; memset(&tm, 0, sizeof(tm)); tm.tm_isdst = -1; localtime_r(&now, &tm); real.tv_sec += tm.tm_gmtoff; correction = real - monotonic; } void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { const char *cp; if ((cp = now.strptime(*buf, "[ %s.%q]"))) { static const char suspend[] = "PM: suspend entry "; static const char resume[] = "PM: suspend exit "; static const char suspended[] = "Suspended for "; if (isspace(*cp)) { ++cp; } if (!strncmp(cp, suspend, sizeof(suspend) - 1)) { calculateCorrection(now, cp + sizeof(suspend) - 1); } else if (!strncmp(cp, resume, sizeof(resume) - 1)) { calculateCorrection(now, cp + sizeof(resume) - 1); } else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) { log_time real; char *endp; real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10); if (*endp == '.') { real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L; if (reverse) { correction -= real; } else { correction += real; } } } convertMonotonicToReal(now); *buf = cp; } else { now = log_time(CLOCK_REALTIME); } } // Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a // compensated start time. void LogKlog::synchronize(const char *buf) { const char *cp = strstr(buf, "] PM: suspend e"); if (!cp) { return; } do { --cp; } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.'))); log_time now; sniffTime(now, &cp, true); char *suspended = strstr(buf, "] Suspended for "); if (!suspended || (suspended > cp)) { return; } cp = suspended; do { --cp; } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.'))); sniffTime(now, &cp, true); } // kernel log prefix, convert to a kernel log priority number static int parseKernelPrio(const char **buf) { int pri = LOG_USER | LOG_INFO; const char *cp = *buf; if (*cp == '<') { pri = 0; while(isdigit(*++cp)) { pri = (pri * 10) + *cp - '0'; } if (*cp == '>') { ++cp; } else { cp = *buf; pri = LOG_USER | LOG_INFO; } *buf = cp; } return pri; } // Convert kernel log priority number into an Android Logger priority number static int convertKernelPrioToAndroidPrio(int pri) { switch(pri & LOG_PRIMASK) { case LOG_EMERG: // FALLTHRU case LOG_ALERT: // FALLTHRU case LOG_CRIT: return ANDROID_LOG_FATAL; case LOG_ERR: return ANDROID_LOG_ERROR; case LOG_WARNING: return ANDROID_LOG_WARN; default: // FALLTHRU case LOG_NOTICE: // FALLTHRU case LOG_INFO: break; case LOG_DEBUG: return ANDROID_LOG_DEBUG; } return ANDROID_LOG_INFO; } // // log a message into the kernel log buffer // // Filter rules to parse