Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 151beac7 authored by Mark Salyzyn's avatar Mark Salyzyn
Browse files

logd: klogd deal with nuls in dmesg 

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
parent ea1a2411

logd/LogAudit.cpp

+3 −3
Original line number Diff line number Diff line
@@ -239,9 +239,9 @@ int LogAudit::logPrint(const char *fmt, ...) { 
    return rc;

}



int LogAudit::log(char *buf) {

int LogAudit::log(char *buf, size_t len) {

    char *audit = strstr(buf, " audit(");

    if (!audit) {

    if (!audit || (audit >= &buf[len])) {

        return 0;

    }
@@ -249,7 +249,7 @@ int LogAudit::log(char *buf) { 


    int rc;

    char *type = strstr(buf, "type=");

    if (type) {

    if (type && (type < &buf[len])) {

        rc = logPrint("%s %s", type, audit + 1);

    } else {

        rc = logPrint("%s", audit + 1);

logd/LogAudit.h

+1 −1
Original line number Diff line number Diff line
@@ -28,7 +28,7 @@ class LogAudit : public SocketListener { 


public:

    LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg);

    int log(char *buf);

    int log(char *buf, size_t len);



protected:

    virtual bool onDataAvailable(SocketClient *cli);

logd/LogKlog.cpp

+134 −82
Original line number Diff line number Diff line
@@ -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)

//  \(\(<[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.

// We allow nuls in content, monitoring the overall length and sub-length of

// the discovered tokens.



#define SIGNATURE_MASK     0xF0

// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
@@ -256,7 +258,7 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { 
                break;

            }

            if (*tok) {

                log(tok);

                log(tok, sublen);

            }

        }

    }
@@ -266,9 +268,11 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { 




void LogKlog::calculateCorrection(const log_time &monotonic,

                                  const char *real_string) {

                                  const char *real_string,

                                  size_t len) {

    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;

    }

    // 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 suspendedStr[] = "Suspended for ";



void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {

    const char *cp;

    if ((cp = now.strptime(*buf, "[ %s.%q]"))) {

static const char *strnstr(const char *s, size_t len, const char *needle) {

    char c;



    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 battery[] = ": battery ";



        if (isspace(*cp)) {

        if (len && isspace(*cp)) {

            ++cp;

            --len;

        }

        *buf = cp;



        const char *b;

        if ((b = strstr(cp, suspendStr))) {

            calculateCorrection(now, b + sizeof(suspendStr) - 1);

        } else if ((b = strstr(cp, resumeStr))) {

            calculateCorrection(now, b + sizeof(resumeStr) - 1);

        } else if (((b = strstr(cp, healthd))) && ((b = strstr(b, battery)))) {

        if (((b = strnstr(cp, len, suspendStr)))

                && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {

            len -= b - cp;

            calculateCorrection(now, b, len);

        } 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

            //     ntp-induced or hardware clock drift.

            // look for " 2???-??-?? ??:??:??.????????? ???"

            const char *tp;

            for (tp = b + sizeof(battery) - 1; *tp && (*tp != '\n'); ++tp) {

                if ((tp[0] == ' ') && (tp[1] == '2') && (tp[5] == '-')) {

                    calculateCorrection(now, tp + 1);

            for (; len && *b && (*b != '\n'); ++b, --len) {

                if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) {

                    calculateCorrection(now, b + 1, len - 1);

                    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;

            char *endp;

            real.tv_sec = strtol(b + sizeof(suspendedStr) - 1, &endp, 10);

            if (*endp == '.') {

            real.tv_sec = strtol(b, &endp, 10);

            if ((*endp == '.') && ((size_t)(endp - b) < len)) {

                unsigned long multiplier = NS_PER_SEC;

                real.tv_nsec = 0;

                while (isdigit(*++endp) && (multiplier /= 10)) {

                len -= endp - b;

                while (--len && isdigit(*++endp) && (multiplier /= 10)) {

                    real.tv_nsec += (*endp - '0') * multiplier;

                }

                if (reverse) {
@@ -338,8 +380,8 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { 
    }

}



pid_t LogKlog::sniffPid(const char *cp) {

    while (*cp) {

pid_t LogKlog::sniffPid(const char *cp, size_t len) {

    while (len) {

        // Mediatek kernels with modified printk

        if (*cp == '[') {

            int pid = 0;
@@ -350,20 +392,21 @@ pid_t LogKlog::sniffPid(const char *cp) { 
            break; // Only the first one

        }

        ++cp;

        --len;

    }

    return 0;

}



// 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;

    const char *cp = *buf;

    if (*cp == '<') {

    if (len && (*cp == '<')) {

        pri = 0;

        while(isdigit(*++cp)) {

        while(--len && isdigit(*++cp)) {

            pri = (pri * 10) + *cp - '0';

        }

        if (*cp == '>') {

        if (len && (*cp == '>')) {

            ++cp;

        } else {

            cp = *buf;
@@ -376,15 +419,15 @@ static int parseKernelPrio(const char **buf) { 


// 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, suspendStr);

void LogKlog::synchronize(const char *buf, size_t len) {

    const char *cp = strnstr(buf, len, suspendStr);

    if (!cp) {

        cp = strstr(buf, resumeStr);

        cp = strnstr(buf, len, resumeStr);

        if (!cp) {

            return;

        }

    } else {

        const char *rp = strstr(buf, resumeStr);

        const char *rp = strnstr(buf, len, resumeStr);

        if (rp && (rp < cp)) {

            cp = rp;

        }
@@ -396,12 +439,12 @@ void LogKlog::synchronize(const char *buf) { 
    if (*cp == '\n') {

        ++cp;

    }

    parseKernelPrio(&cp);

    parseKernelPrio(&cp, len - (cp - buf));



    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)) {

        return;

    }
@@ -413,9 +456,9 @@ void LogKlog::synchronize(const char *buf) { 
    if (*cp == '\n') {

        ++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
@@ -491,19 +534,20 @@ static const char *strnrchr(const char *s, size_t len, char c) { 
//  logd.klogd:

// return -1 if message logd.klogd: <signature>

//

int LogKlog::log(const char *buf) {

    if (auditd && strstr(buf, " audit(")) {

int LogKlog::log(const char *buf, size_t len) {

    if (auditd && strnstr(buf, len, " audit(")) {

        return 0;

    }



    int pri = parseKernelPrio(&buf);

    const char *p = buf;

    int pri = parseKernelPrio(&p, len);



    log_time now;

    sniffTime(now, &buf, false);

    sniffTime(now, &p, len - (p - buf), false);



    // sniff for start marker

    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) {

        uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10);

        if (sig == signature.nsec()) {
@@ -522,7 +566,7 @@ int LogKlog::log(const char *buf) { 
    }



    // 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 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

    // beautify the kernel logs into an Android Logging format; the goal is

    // admirable but costly.

    while (isspace(*buf)) {

        ++buf;

    while ((isspace(*p) || !*p) && (p < &buf[len])) {

        ++p;

    }

    if (!*buf) {

    if (p >= &buf[len]) { // timestamp, no content

        return 0;

    }

    start = buf;

    start = p;

    const char *tag = "";

    const char *etag = tag;

    if (!isspace(*buf)) {

    size_t taglen = len - (p - buf);

    if (!isspace(*p) && *p) {

        const char *bt, *et, *cp;



        bt = buf;

        if (!strncmp(buf, "[INFO]", 6)) {

        bt = p;

        if (!strncmp(p, "[INFO]", 6)) {

            // <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 [ ... ]

           if (*et == '[') {

               while (*et && *et != ']') {

               while (taglen && *et && *et != ']') {

                   ++et;

                   --taglen;

               }

            }

        }

        for(cp = et; isspace(*cp); ++cp);

        for(cp = et; taglen && isspace(*cp); ++cp, --taglen);

        size_t size;



        if (*cp == ':') {

            // One Word

            tag = bt;

            etag = et;

            buf = cp + 1;

        } else {

            p = cp + 1;

        } else if (taglen) {

            size = et - bt;

            if (strncmp(bt, cp, size)) {

                // <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
@@ -571,67 +618,72 @@ int LogKlog::log(const char *buf) { 
                        && !strncmp(bt, cp, size - 5)) {

                    const char *b = cp;

                    cp += size - 5;

                    taglen -= size - 5;

                    if (*cp == '.') {

                        while (!isspace(*++cp) && (*cp != ':'));

                        while (--taglen && !isspace(*++cp) && (*cp != ':'));

                        const char *e;

                        for(e = cp; isspace(*cp); ++cp);

                        for(e = cp; taglen && isspace(*cp); ++cp, --taglen);

                        if (*cp == ':') {

                            tag = b;

                            etag = e;

                            buf = cp + 1;

                            p = cp + 1;

                        }

                    }

                } else {

                    while (!isspace(*++cp) && (*cp != ':'));

                    while (--taglen && !isspace(*++cp) && (*cp != ':'));

                    const char *e;

                    for(e = cp; isspace(*cp); ++cp);

                    for(e = cp; taglen && isspace(*cp); ++cp, --taglen);

                    // Two words

                    if (*cp == ':') {

                        tag = bt;

                        etag = e;

                        buf = cp + 1;

                        p = cp + 1;

                    }

                }

            } else if (isspace(cp[size])) {

                cp += size;

                while (isspace(*++cp));

                taglen -= size;

                while (--taglen && isspace(*++cp));

                // <PRI>[<TIME>] <tag> <tag> : message

                if (*cp == ':') {

                    tag = bt;

                    etag = et;

                    buf = cp + 1;

                    p = cp + 1;

                }

            } else if (cp[size] == ':') {

                // <PRI>[<TIME>] <tag> <tag> : message

                tag = bt;

                etag = et;

                buf = cp + size + 1;

                p = cp + size + 1;

            } else if ((cp[size] == '.') || isdigit(cp[size])) {

                // <PRI>[<TIME>] <tag> '<tag>.<num>' : message

                // <PRI>[<TIME>] <tag> '<tag><num>' : message

                const char *b = cp;

                cp += size;

                while (!isspace(*++cp) && (*cp != ':'));

                taglen -= size;

                while (--taglen && !isspace(*++cp) && (*cp != ':'));

                const char *e = cp;

                while (isspace(*cp)) {

                while (taglen && isspace(*cp)) {

                    ++cp;

                    --taglen;

                }

                if (*cp == ':') {

                    tag = b;

                    etag = e;

                    buf = cp + 1;

                    p = cp + 1;

                }

            } else {

                while (!isspace(*++cp) && (*cp != ':'));

                while (--taglen && !isspace(*++cp) && (*cp != ':'));

                const char *e = cp;

                while (isspace(*cp)) {

                while (taglen && isspace(*cp)) {

                    ++cp;

                    --taglen;

                }

                // Two words

                if (*cp == ':') {

                    tag = bt;

                    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])))

            // blacklist

                || ((size == 3) && !strncmp(tag, "CPU", 3))

                || ((size == 7) && !strncmp(tag, "WARNING", 7))

                || ((size == 5) && !strncmp(tag, "ERROR", 5))

                || ((size == 4) && !strncmp(tag, "INFO", 4))) {

            buf = start;

                || ((size == 7) && !strncasecmp(tag, "WARNING", 7))

                || ((size == 5) && !strncasecmp(tag, "ERROR", 5))

                || ((size == 4) && !strncasecmp(tag, "INFO", 4))) {

            p = start;

            etag = tag = "";

        }

    }

    // Suppress additional stutter in tag:

    //   eg: [143:healthd]healthd -> [143:healthd]

    size_t taglen = etag - tag;

    taglen = etag - tag;

    // Mediatek-special printk induced stutter

    const char *mp = strnrchr(tag, ']', taglen);

    if (mp && (++mp < etag)) {
@@ -662,17 +714,17 @@ int LogKlog::log(const char *buf) { 
        }

    }

    // skip leading space

    while (isspace(*buf)) {

        ++buf;

    while ((isspace(*p) || !*p) && (p < &buf[len])) {

        ++p;

    }

    // truncate trailing space

    size_t b = strlen(buf);

    while (b && isspace(buf[b-1])) {

    // truncate trailing space or nuls

    size_t b = len - (p - buf);

    while (b && (isspace(p[b-1]) || !p[b-1])) {

        --b;

    }

    // trick ... allow tag with empty content to be logged. log() drops empty

    if (!b && taglen) {

        buf = " ";

        p = " ";

        b = 1;

    }

    size_t n = 1 + taglen + 1 + b + 1;
@@ -695,13 +747,13 @@ int LogKlog::log(const char *buf) { 
    ++np;



    // Copy parsed tag following priority

    strncpy(np, tag, taglen);

    memcpy(np, tag, taglen);

    np += taglen;

    *np = '\0';

    ++np;



    // Copy main message to the remainder

    strncpy(np, buf, b);

    memcpy(np, p, b);

    np[b] = '\0';



    // Log message

logd/LogKlog.h

+6 −5
Original line number Diff line number Diff line
@@ -40,15 +40,16 @@ class LogKlog : public SocketListener { 


public:

    LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd);

    int log(const char *buf);

    void synchronize(const char *buf);

    int log(const char *buf, size_t len);

    void synchronize(const char *buf, size_t len);



    static void convertMonotonicToReal(log_time &real) { real += correction; }



protected:

    void sniffTime(log_time &now, const char **buf, bool reverse);

    pid_t sniffPid(const char *buf);

    void calculateCorrection(const log_time &monotonic, const char *real_string);

    void sniffTime(log_time &now, const char **buf, size_t len, bool reverse);

    pid_t sniffPid(const char *buf, size_t len);

    void calculateCorrection(const log_time &monotonic,

                             const char *real_string, size_t len);

    virtual bool onDataAvailable(SocketClient *cli);



};

logd/main.cpp

+3 −3
Original line number Diff line number Diff line
@@ -301,7 +301,7 @@ static void readDmesg(LogAudit *al, LogKlog *kl) { 
    buf[--len] = '\0';



    if (kl) {

        kl->synchronize(buf.get());

        kl->synchronize(buf.get(), len);

    }



    size_t sublen;
@@ -309,10 +309,10 @@ static void readDmesg(LogAudit *al, LogKlog *kl) { 
         (rc >= 0) && ((tok = log_strntok_r(tok, &len, &ptr, &sublen)));

         tok = NULL) {

        if (al) {

            rc = al->log(tok);

            rc = al->log(tok, sublen);

        }

        if (kl) {

            rc = kl->log(tok);

            rc = kl->log(tok, sublen);

        }

    }

}