ACPR/android_system_core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

logd: klogd deal with nuls in dmesg

Browse source 
(cherry pick from commit 151beac76d)

Switch to using string and length in all transactions, treating
trailing nuls the same as spaces.

ToDo: change dumpstate (bugreport) to use logcat -b printable _regardless_

Bug: 23517551
Change-Id: I42162365e6bf8ed79d356e7b689a673902116fdb
This commit is contained in:
Mark Salyzyn 2015-09-04 11:37:42 -07:00 • committed by Rom Lemarchand
parent f9e4d0b6b5
commit 4efc87e5eb
5 changed files with 147 additions and 94 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
logd/LogAudit.cpp
View file

@ -239,9 +239,9 @@ int LogAudit::logPrint(const char *fmt, ...) {
return rc; return rc;
} }
int LogAudit::log(char *buf) { int LogAudit::log(char *buf, size_t len) {
char *audit = strstr(buf, " audit("); char *audit = strstr(buf, " audit(");
if (!audit) { if (!audit || (audit >= &buf[len])) {
return 0; return 0;
} }
@ -249,7 +249,7 @@ int LogAudit::log(char *buf) {
int rc; int rc;
char *type = strstr(buf, "type="); char *type = strstr(buf, "type=");
if (type) { if (type && (type < &buf[len])) {
rc = logPrint("%s %s", type, audit + 1); rc = logPrint("%s %s", type, audit + 1);
} else { } else {
rc = logPrint("%s", audit + 1); rc = logPrint("%s", audit + 1);

2
logd/LogAudit.h
View file

@ -28,7 +28,7 @@ class LogAudit : public SocketListener {
public: public:
LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg); LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg);
int log(char *buf); int log(char *buf, size_t len);
protected: protected:
virtual bool onDataAvailable(SocketClient *cli); virtual bool onDataAvailable(SocketClient *cli);

216
logd/LogKlog.cpp
View file

@ -81,6 +81,8 @@ static char *is_timestamp(char *s, size_t len) {
// Like strtok_r with "\r\n" except that we look for log signatures (regex) // Like strtok_r with "\r\n" except that we look for log signatures (regex)
// \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \) // \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \)
// and split if we see a second one without a newline. // and split if we see a second one without a newline.
// We allow nuls in content, monitoring the overall length and sub-length of
// the discovered tokens.
#define SIGNATURE_MASK 0xF0 #define SIGNATURE_MASK 0xF0
// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature // <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
@ -256,7 +258,7 @@ bool LogKlog::onDataAvailable(SocketClient *cli) {
break; break;
} }
if (*tok) { if (*tok) {
log(tok); log(tok, sublen);
} }
} }
} }
@ -266,9 +268,11 @@ bool LogKlog::onDataAvailable(SocketClient *cli) {
void LogKlog::calculateCorrection(const log_time &monotonic, void LogKlog::calculateCorrection(const log_time &monotonic,
const char *real_string) { const char *real_string,
size_t len) {
log_time real; log_time real;
if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) { const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC");
if (!ep || (ep > &real_string[len])) {
return; return;
} }
// kernel report UTC, log_time::strptime is localtime from calendar. // kernel report UTC, log_time::strptime is localtime from calendar.
@ -287,41 +291,79 @@ static const char suspendStr[] = "PM: suspend entry ";
static const char resumeStr[] = "PM: suspend exit "; static const char resumeStr[] = "PM: suspend exit ";
static const char suspendedStr[] = "Suspended for "; static const char suspendedStr[] = "Suspended for ";
void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { static const char *strnstr(const char *s, size_t len, const char *needle) {
const char *cp; char c;
if ((cp = now.strptime(*buf, "[ %s.%q]"))) {
if (!len) {
return NULL;
}
if ((c = *needle++) != 0) {
size_t needleLen = strlen(needle);
do {
do {
if (len <= needleLen) {
return NULL;
}
--len;
} while (*s++ != c);
} while (memcmp(s, needle, needleLen) != 0);
s--;
}
return s;
}
void LogKlog::sniffTime(log_time &now,
const char **buf, size_t len,
bool reverse) {
const char *cp = now.strptime(*buf, "[ %s.%q]");
if (cp && (cp >= &(*buf)[len])) {
cp = NULL;
}
len -= cp - *buf;
if (cp) {
static const char healthd[] = "healthd"; static const char healthd[] = "healthd";
static const char battery[] = ": battery "; static const char battery[] = ": battery ";
if (isspace(*cp)) { if (len && isspace(*cp)) {
++cp; ++cp;
--len;
} }
*buf = cp; *buf = cp;
const char *b; const char *b;
if ((b = strstr(cp, suspendStr))) { if (((b = strnstr(cp, len, suspendStr)))
calculateCorrection(now, b + sizeof(suspendStr) - 1); && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
} else if ((b = strstr(cp, resumeStr))) { len -= b - cp;
calculateCorrection(now, b + sizeof(resumeStr) - 1); calculateCorrection(now, b, len);
} else if (((b = strstr(cp, healthd))) && ((b = strstr(b, battery)))) { } else if (((b = strnstr(cp, len, resumeStr)))
&& ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) {
len -= b - cp;
calculateCorrection(now, b, len);
} else if (((b = strnstr(cp, len, healthd)))
&& ((size_t)((b += sizeof(healthd) - 1) - cp) < len)
&& ((b = strnstr(b, len -= b - cp, battery)))
&& ((size_t)((b += sizeof(battery) - 1) - cp) < len)) {
len -= b - cp;
// NB: healthd is roughly 150us late, worth the price to deal with // NB: healthd is roughly 150us late, worth the price to deal with
// ntp-induced or hardware clock drift. // ntp-induced or hardware clock drift.
// look for " 2???-??-?? ??:??:??.????????? ???" // look for " 2???-??-?? ??:??:??.????????? ???"
const char *tp; for (; len && *b && (*b != '\n'); ++b, --len) {
for (tp = b + sizeof(battery) - 1; *tp && (*tp != '\n'); ++tp) { if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) {
if ((tp[0] == ' ') && (tp[1] == '2') && (tp[5] == '-')) { calculateCorrection(now, b + 1, len - 1);
calculateCorrection(now, tp + 1);
break; break;
} }
} }
} else if ((b = strstr(cp, suspendedStr))) { } else if (((b = strnstr(cp, len, suspendedStr)))
&& ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
len -= b - cp;
log_time real; log_time real;
char *endp; char *endp;
real.tv_sec = strtol(b + sizeof(suspendedStr) - 1, &endp, 10); real.tv_sec = strtol(b, &endp, 10);
if (*endp == '.') { if ((*endp == '.') && ((size_t)(endp - b) < len)) {
unsigned long multiplier = NS_PER_SEC; unsigned long multiplier = NS_PER_SEC;
real.tv_nsec = 0; real.tv_nsec = 0;
while (isdigit(*++endp) && (multiplier /= 10)) { len -= endp - b;
while (--len && isdigit(*++endp) && (multiplier /= 10)) {
real.tv_nsec += (*endp - '0') * multiplier; real.tv_nsec += (*endp - '0') * multiplier;
} }
if (reverse) { if (reverse) {
@ -338,8 +380,8 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
} }
} }
pid_t LogKlog::sniffPid(const char *cp) { pid_t LogKlog::sniffPid(const char *cp, size_t len) {
while (*cp) { while (len) {
// Mediatek kernels with modified printk // Mediatek kernels with modified printk
if (*cp == '[') { if (*cp == '[') {
int pid = 0; int pid = 0;
@ -350,20 +392,21 @@ pid_t LogKlog::sniffPid(const char *cp) {
break; // Only the first one break; // Only the first one
} }
++cp; ++cp;
--len;
} }
return 0; return 0;
} }
// kernel log prefix, convert to a kernel log priority number // kernel log prefix, convert to a kernel log priority number
static int parseKernelPrio(const char **buf) { static int parseKernelPrio(const char **buf, size_t len) {
int pri = LOG_USER | LOG_INFO; int pri = LOG_USER | LOG_INFO;
const char *cp = *buf; const char *cp = *buf;
if (*cp == '<') { if (len && (*cp == '<')) {
pri = 0; pri = 0;
while(isdigit(*++cp)) { while(--len && isdigit(*++cp)) {
pri = (pri * 10) + *cp - '0'; pri = (pri * 10) + *cp - '0';
} }
if (*cp == '>') { if (len && (*cp == '>')) {
++cp; ++cp;
} else { } else {
cp = *buf; cp = *buf;
@ -376,15 +419,15 @@ static int parseKernelPrio(const char **buf) {
// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a // Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
// compensated start time. // compensated start time.
void LogKlog::synchronize(const char *buf) { void LogKlog::synchronize(const char *buf, size_t len) {
const char *cp = strstr(buf, suspendStr); const char *cp = strnstr(buf, len, suspendStr);
if (!cp) { if (!cp) {
cp = strstr(buf, resumeStr); cp = strnstr(buf, len, resumeStr);
if (!cp) { if (!cp) {
return; return;
} }
} else { } else {
const char *rp = strstr(buf, resumeStr); const char *rp = strnstr(buf, len, resumeStr);
if (rp && (rp < cp)) { if (rp && (rp < cp)) {
cp = rp; cp = rp;
} }
@ -396,12 +439,12 @@ void LogKlog::synchronize(const char *buf) {
if (*cp == '\n') { if (*cp == '\n') {
++cp; ++cp;
} }
parseKernelPrio(&cp); parseKernelPrio(&cp, len - (cp - buf));
log_time now; log_time now;
sniffTime(now, &cp, true); sniffTime(now, &cp, len - (cp - buf), true);
char *suspended = strstr(buf, suspendedStr); const char *suspended = strnstr(buf, len, suspendedStr);
if (!suspended || (suspended > cp)) { if (!suspended || (suspended > cp)) {
return; return;
} }
@ -413,9 +456,9 @@ void LogKlog::synchronize(const char *buf) {
if (*cp == '\n') { if (*cp == '\n') {
++cp; ++cp;
} }
parseKernelPrio(&cp); parseKernelPrio(&cp, len - (cp - buf));
sniffTime(now, &cp, true); sniffTime(now, &cp, len - (cp - buf), true);
} }
// Convert kernel log priority number into an Android Logger priority number // Convert kernel log priority number into an Android Logger priority number
@ -491,19 +534,20 @@ static const char *strnrchr(const char *s, size_t len, char c) {
// logd.klogd: // logd.klogd:
// return -1 if message logd.klogd: <signature> // return -1 if message logd.klogd: <signature>
// //
int LogKlog::log(const char *buf) { int LogKlog::log(const char *buf, size_t len) {
if (auditd && strstr(buf, " audit(")) { if (auditd && strnstr(buf, len, " audit(")) {
return 0; return 0;
} }
int pri = parseKernelPrio(&buf); const char *p = buf;
int pri = parseKernelPrio(&p, len);
log_time now; log_time now;
sniffTime(now, &buf, false); sniffTime(now, &p, len - (p - buf), false);
// sniff for start marker // sniff for start marker
const char klogd_message[] = "logd.klogd: "; const char klogd_message[] = "logd.klogd: ";
const char *start = strstr(buf, klogd_message); const char *start = strnstr(p, len - (p - buf), klogd_message);
if (start) { if (start) {
uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10); uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10);
if (sig == signature.nsec()) { if (sig == signature.nsec()) {
@ -522,7 +566,7 @@ int LogKlog::log(const char *buf) {
} }
// Parse pid, tid and uid // Parse pid, tid and uid
const pid_t pid = sniffPid(buf); const pid_t pid = sniffPid(p, len - (p - buf));
const pid_t tid = pid; const pid_t tid = pid;
const uid_t uid = pid ? logbuf->pidToUid(pid) : 0; const uid_t uid = pid ? logbuf->pidToUid(pid) : 0;
@ -530,40 +574,43 @@ int LogKlog::log(const char *buf) {
// Some may view the following as an ugly heuristic, the desire is to // Some may view the following as an ugly heuristic, the desire is to
// beautify the kernel logs into an Android Logging format; the goal is // beautify the kernel logs into an Android Logging format; the goal is
// admirable but costly. // admirable but costly.
while (isspace(*buf)) { while ((isspace(*p) || !*p) && (p < &buf[len])) {
++buf; ++p;
} }
if (!*buf) { if (p >= &buf[len]) { // timestamp, no content
return 0; return 0;
} }
start = buf; start = p;
const char *tag = ""; const char *tag = "";
const char *etag = tag; const char *etag = tag;
if (!isspace(*buf)) { size_t taglen = len - (p - buf);
if (!isspace(*p) && *p) {
const char *bt, *et, *cp; const char *bt, *et, *cp;
bt = buf; bt = p;
if (!strncmp(buf, "[INFO]", 6)) { if (!strncmp(p, "[INFO]", 6)) {
// <PRI>[<TIME>] "[INFO]"<tag> ":" message // <PRI>[<TIME>] "[INFO]"<tag> ":" message
bt = buf + 6; bt = p + 6;
taglen -= 6;
} }
for(et = bt; *et && (*et != ':') && !isspace(*et); ++et) { for(et = bt; taglen && *et && (*et != ':') && !isspace(*et); ++et, --taglen) {
// skip ':' within [ ... ] // skip ':' within [ ... ]
if (*et == '[') { if (*et == '[') {
while (*et && *et != ']') { while (taglen && *et && *et != ']') {
++et; ++et;
--taglen;
} }
} }
} }
for(cp = et; isspace(*cp); ++cp); for(cp = et; taglen && isspace(*cp); ++cp, --taglen);
size_t size; size_t size;
if (*cp == ':') { if (*cp == ':') {
// One Word // One Word
tag = bt; tag = bt;
etag = et; etag = et;
buf = cp + 1; p = cp + 1;
} else { } else if (taglen) {
size = et - bt; size = et - bt;
if (strncmp(bt, cp, size)) { if (strncmp(bt, cp, size)) {
// <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message // <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
@ -571,67 +618,72 @@ int LogKlog::log(const char *buf) {
&& !strncmp(bt, cp, size - 5)) { && !strncmp(bt, cp, size - 5)) {
const char *b = cp; const char *b = cp;
cp += size - 5; cp += size - 5;
taglen -= size - 5;
if (*cp == '.') { if (*cp == '.') {
while (!isspace(*++cp) && (*cp != ':')); while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e; const char *e;
for(e = cp; isspace(*cp); ++cp); for(e = cp; taglen && isspace(*cp); ++cp, --taglen);
if (*cp == ':') { if (*cp == ':') {
tag = b; tag = b;
etag = e; etag = e;
buf = cp + 1; p = cp + 1;
} }
} }
} else { } else {
while (!isspace(*++cp) && (*cp != ':')); while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e; const char *e;
for(e = cp; isspace(*cp); ++cp); for(e = cp; taglen && isspace(*cp); ++cp, --taglen);
// Two words // Two words
if (*cp == ':') { if (*cp == ':') {
tag = bt; tag = bt;
etag = e; etag = e;
buf = cp + 1; p = cp + 1;
} }
} }
} else if (isspace(cp[size])) { } else if (isspace(cp[size])) {
cp += size; cp += size;
while (isspace(*++cp)); taglen -= size;
while (--taglen && isspace(*++cp));
// <PRI>[<TIME>] <tag> <tag> : message // <PRI>[<TIME>] <tag> <tag> : message
if (*cp == ':') { if (*cp == ':') {
tag = bt; tag = bt;
etag = et; etag = et;
buf = cp + 1; p = cp + 1;
} }
} else if (cp[size] == ':') { } else if (cp[size] == ':') {
// <PRI>[<TIME>] <tag> <tag> : message // <PRI>[<TIME>] <tag> <tag> : message
tag = bt; tag = bt;
etag = et; etag = et;
buf = cp + size + 1; p = cp + size + 1;
} else if ((cp[size] == '.') || isdigit(cp[size])) { } else if ((cp[size] == '.') || isdigit(cp[size])) {
// <PRI>[<TIME>] <tag> '<tag>.<num>' : message // <PRI>[<TIME>] <tag> '<tag>.<num>' : message
// <PRI>[<TIME>] <tag> '<tag><num>' : message // <PRI>[<TIME>] <tag> '<tag><num>' : message
const char *b = cp; const char *b = cp;
cp += size; cp += size;
while (!isspace(*++cp) && (*cp != ':')); taglen -= size;
while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e = cp; const char *e = cp;
while (isspace(*cp)) { while (taglen && isspace(*cp)) {
++cp; ++cp;
--taglen;
} }
if (*cp == ':') { if (*cp == ':') {
tag = b; tag = b;
etag = e; etag = e;
buf = cp + 1; p = cp + 1;
} }
} else { } else {
while (!isspace(*++cp) && (*cp != ':')); while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e = cp; const char *e = cp;
while (isspace(*cp)) { while (taglen && isspace(*cp)) {
++cp; ++cp;
--taglen;
} }
// Two words // Two words
if (*cp == ':') { if (*cp == ':') {
tag = bt; tag = bt;
etag = e; etag = e;
buf = cp + 1; p = cp + 1;
} }
} }
} }
@ -643,16 +695,16 @@ int LogKlog::log(const char *buf) {
|| ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2]))) || ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2])))
// blacklist // blacklist
|| ((size == 3) && !strncmp(tag, "CPU", 3)) || ((size == 3) && !strncmp(tag, "CPU", 3))
|| ((size == 7) && !strncmp(tag, "WARNING", 7)) || ((size == 7) && !strncasecmp(tag, "WARNING", 7))
|| ((size == 5) && !strncmp(tag, "ERROR", 5)) || ((size == 5) && !strncasecmp(tag, "ERROR", 5))
|| ((size == 4) && !strncmp(tag, "INFO", 4))) { || ((size == 4) && !strncasecmp(tag, "INFO", 4))) {
buf = start; p = start;
etag = tag = ""; etag = tag = "";
} }
} }
// Suppress additional stutter in tag: // Suppress additional stutter in tag:
// eg: [143:healthd]healthd -> [143:healthd] // eg: [143:healthd]healthd -> [143:healthd]
size_t taglen = etag - tag; taglen = etag - tag;
// Mediatek-special printk induced stutter // Mediatek-special printk induced stutter
const char *mp = strnrchr(tag, ']', taglen); const char *mp = strnrchr(tag, ']', taglen);
if (mp && (++mp < etag)) { if (mp && (++mp < etag)) {
@ -662,17 +714,17 @@ int LogKlog::log(const char *buf) {
} }
} }
// skip leading space // skip leading space
while (isspace(*buf)) { while ((isspace(*p) || !*p) && (p < &buf[len])) {
++buf; ++p;
} }
// truncate trailing space // truncate trailing space or nuls
size_t b = strlen(buf); size_t b = len - (p - buf);
while (b && isspace(buf[b-1])) { while (b && (isspace(p[b-1]) || !p[b-1])) {
--b; --b;
} }
// trick ... allow tag with empty content to be logged. log() drops empty // trick ... allow tag with empty content to be logged. log() drops empty
if (!b && taglen) { if (!b && taglen) {
buf = " "; p = " ";
b = 1; b = 1;
} }
size_t n = 1 + taglen + 1 + b + 1; size_t n = 1 + taglen + 1 + b + 1;
@ -695,13 +747,13 @@ int LogKlog::log(const char *buf) {
++np; ++np;
// Copy parsed tag following priority // Copy parsed tag following priority
strncpy(np, tag, taglen); memcpy(np, tag, taglen);
np += taglen; np += taglen;
*np = '\0'; *np = '\0';
++np; ++np;
// Copy main message to the remainder // Copy main message to the remainder
strncpy(np, buf, b); memcpy(np, p, b);
np[b] = '\0'; np[b] = '\0';
// Log message // Log message

11
logd/LogKlog.h
View file

@ -40,15 +40,16 @@ class LogKlog : public SocketListener {
public: public:
LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd); LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd);
int log(const char *buf); int log(const char *buf, size_t len);
void synchronize(const char *buf); void synchronize(const char *buf, size_t len);
static void convertMonotonicToReal(log_time &real) { real += correction; } static void convertMonotonicToReal(log_time &real) { real += correction; }
protected: protected:
void sniffTime(log_time &now, const char **buf, bool reverse); void sniffTime(log_time &now, const char **buf, size_t len, bool reverse);
pid_t sniffPid(const char *buf); pid_t sniffPid(const char *buf, size_t len);
void calculateCorrection(const log_time &monotonic, const char *real_string); void calculateCorrection(const log_time &monotonic,
const char *real_string, size_t len);
virtual bool onDataAvailable(SocketClient *cli); virtual bool onDataAvailable(SocketClient *cli);
}; };

6
logd/main.cpp
View file

@ -305,7 +305,7 @@ static void readDmesg(LogAudit *al, LogKlog *kl) {
buf[--len] = '\0'; buf[--len] = '\0';
if (kl) { if (kl) {
kl->synchronize(buf.get()); kl->synchronize(buf.get(), len);
} }
size_t sublen; size_t sublen;
@ -313,10 +313,10 @@ static void readDmesg(LogAudit *al, LogKlog *kl) {
(rc >= 0) && ((tok = log_strntok_r(tok, &len, &ptr, &sublen))); (rc >= 0) && ((tok = log_strntok_r(tok, &len, &ptr, &sublen)));
tok = NULL) { tok = NULL) {
if (al) { if (al) {
rc = al->log(tok); rc = al->log(tok, sublen);
} }
if (kl) { if (kl) {
rc = kl->log(tok); rc = kl->log(tok, sublen);
} }
} }
} }