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
38static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
39
40// List of the _only_ needles we supply here to android::strnstr
41static const char suspendStr[] = "PM: suspend entry ";
42static const char resumeStr[] = "PM: suspend exit ";
43static const char suspendedStr[] = "Suspended for ";
44static const char healthdStr[] = "healthd";
45static const char batteryStr[] = ": battery ";
46static const char auditStr[] = " audit(";
47static 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 '>'
52static 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 ']'
65static 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
99char* 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
200log_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
205LogKlog::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
222bool 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
266void 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
296void 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
368pid_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
415static 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.
436void 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
475static 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
504static 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//
547int 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) {
829        reader->notifyNewLog();
830    }
831
832    return rc;
833}
834