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 <log/logger.h>
29#include <private/android_filesystem_config.h>
30
31#include "LogBuffer.h"
32#include "LogKlog.h"
33#include "LogReader.h"
34
35#define KMSG_PRIORITY(PRI)           \
36    '<',                             \
37    '0' + (LOG_SYSLOG | (PRI)) / 10, \
38    '0' + (LOG_SYSLOG | (PRI)) % 10, \
39    '>'
40
41static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
42
43// Parsing is hard
44
45// called if we see a '<', s is the next character, returns pointer after '>'
46static char *is_prio(char *s, size_t len) {
47    if (!len || !isdigit(*s++)) {
48        return NULL;
49    }
50    --len;
51    static const size_t max_prio_len = (len < 4) ? len : 4;
52    size_t priolen = 0;
53    char c;
54    while (((c = *s++)) && (++priolen <= max_prio_len)) {
55        if (!isdigit(c)) {
56            return ((c == '>') && (*s == '[')) ? s : NULL;
57        }
58    }
59    return NULL;
60}
61
62// called if we see a '[', s is the next character, returns pointer after ']'
63static char *is_timestamp(char *s, size_t len) {
64    while (len && (*s == ' ')) {
65        ++s;
66        --len;
67    }
68    if (!len || !isdigit(*s++)) {
69        return NULL;
70    }
71    --len;
72    bool first_period = true;
73    char c;
74    while (len && ((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 : NULL;
80        }
81    }
82    return NULL;
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\}\|[[] *[0-9]+[.][0-9]+[]] \)
87// and split if we see a second one without a newline.
88// We allow nuls in content, monitoring the overall length and sub-length of
89// the discovered tokens.
90
91#define SIGNATURE_MASK     0xF0
92// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
93#define LESS_THAN_SIG      SIGNATURE_MASK
94#define OPEN_BRACKET_SIG   ((SIGNATURE_MASK << 1) & SIGNATURE_MASK)
95// space is one more than <digit> of 9
96#define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10))
97
98char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) {
99    *sublen = 0;
100    if (!*len) {
101        return NULL;
102    }
103    if (!s) {
104        if (!(s = *last)) {
105            return NULL;
106        }
107        // fixup for log signature split <,
108        // LESS_THAN_SIG + <digit>
109        if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) {
110            *s = (*s & ~SIGNATURE_MASK) + '0';
111            *--s = '<';
112            ++*len;
113        }
114        // fixup for log signature split [,
115        // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit>
116        if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) {
117            if (*s == OPEN_BRACKET_SPACE) {
118                *s = ' ';
119            } else {
120                *s = (*s & ~SIGNATURE_MASK) + '0';
121            }
122            *--s = '[';
123            ++*len;
124        }
125    }
126
127    while (*len && ((*s == '\r') || (*s == '\n'))) {
128        ++s;
129        --*len;
130    }
131
132    if (!*len) {
133        *last = NULL;
134        return NULL;
135    }
136    char *peek, *tok = s;
137
138    for (;;) {
139        if (*len == 0) {
140            *last = NULL;
141            return tok;
142        }
143        char c = *s++;
144        --*len;
145        size_t adjust;
146        switch (c) {
147        case '\r':
148        case '\n':
149            s[-1] = '\0';
150            *last = s;
151            return tok;
152
153        case '<':
154            peek = is_prio(s, *len);
155            if (!peek) {
156                break;
157            }
158            if (s != (tok + 1)) { // not first?
159                s[-1] = '\0';
160                *s &= ~SIGNATURE_MASK;
161                *s |= LESS_THAN_SIG; // signature for '<'
162                *last = s;
163                return tok;
164            }
165            adjust = peek - s;
166            if (adjust > *len) {
167                adjust = *len;
168            }
169            *sublen += adjust;
170            *len -= adjust;
171            s = peek;
172            if ((*s == '[') && ((peek = is_timestamp(s + 1, *len - 1)))) {
173                adjust = peek - s;
174                if (adjust > *len) {
175                    adjust = *len;
176                }
177                *sublen += adjust;
178                *len -= adjust;
179                s = peek;
180            }
181            break;
182
183        case '[':
184            peek = is_timestamp(s, *len);
185            if (!peek) {
186                break;
187            }
188            if (s != (tok + 1)) { // not first?
189                s[-1] = '\0';
190                if (*s == ' ') {
191                    *s = OPEN_BRACKET_SPACE;
192                } else {
193                    *s &= ~SIGNATURE_MASK;
194                    *s |= OPEN_BRACKET_SIG; // signature for '['
195                }
196                *last = s;
197                return tok;
198            }
199            adjust = peek - s;
200            if (adjust > *len) {
201                adjust = *len;
202            }
203            *sublen += adjust;
204            *len -= adjust;
205            s = peek;
206            break;
207        }
208        ++*sublen;
209    }
210    // NOTREACHED
211}
212
213log_time LogKlog::correction =
214    (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTONIC))
215        ? log_time::EPOCH
216        : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC));
217
218LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) :
219        SocketListener(fdRead, false),
220        logbuf(buf),
221        reader(reader),
222        signature(CLOCK_MONOTONIC),
223        initialized(false),
224        enableLogging(true),
225        auditd(auditd) {
226    static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n";
227    char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4];
228    snprintf(buffer, sizeof(buffer), klogd_message, priority_message,
229        signature.nsec());
230    write(fdWrite, buffer, strlen(buffer));
231}
232
233bool LogKlog::onDataAvailable(SocketClient *cli) {
234    if (!initialized) {
235        prctl(PR_SET_NAME, "logd.klogd");
236        initialized = true;
237        enableLogging = false;
238    }
239
240    char buffer[LOGGER_ENTRY_MAX_PAYLOAD];
241    size_t len = 0;
242
243    for(;;) {
244        ssize_t retval = 0;
245        if ((sizeof(buffer) - 1 - len) > 0) {
246            retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len);
247        }
248        if ((retval == 0) && (len == 0)) {
249            break;
250        }
251        if (retval < 0) {
252            return false;
253        }
254        len += retval;
255        bool full = len == (sizeof(buffer) - 1);
256        char *ep = buffer + len;
257        *ep = '\0';
258        size_t sublen;
259        for(char *ptr = NULL, *tok = buffer;
260                ((tok = log_strntok_r(tok, &len, &ptr, &sublen)));
261                tok = NULL) {
262            if (((tok + sublen) >= ep) && (retval != 0) && full) {
263                memmove(buffer, tok, sublen);
264                len = sublen;
265                break;
266            }
267            if (*tok) {
268                log(tok, sublen);
269            }
270        }
271    }
272
273    return true;
274}
275
276
277void LogKlog::calculateCorrection(const log_time &monotonic,
278                                  const char *real_string,
279                                  size_t len) {
280    log_time real;
281    const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC");
282    if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) {
283        return;
284    }
285    // kernel report UTC, log_time::strptime is localtime from calendar.
286    // Bionic and liblog strptime does not support %z or %Z to pick up
287    // timezone so we are calculating our own correction.
288    time_t now = real.tv_sec;
289    struct tm tm;
290    memset(&tm, 0, sizeof(tm));
291    tm.tm_isdst = -1;
292    localtime_r(&now, &tm);
293    if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > (long)real.tv_sec)) {
294        real = log_time::EPOCH;
295    } else {
296        real.tv_sec += tm.tm_gmtoff;
297    }
298    if (monotonic > real) {
299        correction = log_time::EPOCH;
300    } else {
301        correction = real - monotonic;
302    }
303}
304
305static const char suspendStr[] = "PM: suspend entry ";
306static const char resumeStr[] = "PM: suspend exit ";
307static const char suspendedStr[] = "Suspended for ";
308
309static const char *strnstr(const char *s, size_t len, const char *needle) {
310    char c;
311
312    if (!len) {
313        return NULL;
314    }
315    if ((c = *needle++) != 0) {
316        size_t needleLen = strlen(needle);
317        do {
318            do {
319                if (len <= needleLen) {
320                    return NULL;
321                }
322                --len;
323            } while (*s++ != c);
324        } while (fast<memcmp>(s, needle, needleLen));
325        s--;
326    }
327    return s;
328}
329
330void LogKlog::sniffTime(log_time &now,
331                        const char **buf, size_t len,
332                        bool reverse) {
333    const char *cp = now.strptime(*buf, "[ %s.%q]");
334    if (cp && (cp >= &(*buf)[len])) {
335        cp = NULL;
336    }
337    if (cp) {
338        static const char healthd[] = "healthd";
339        static const char battery[] = ": battery ";
340
341        len -= cp - *buf;
342        if (len && isspace(*cp)) {
343            ++cp;
344            --len;
345        }
346        *buf = cp;
347
348        if (isMonotonic()) {
349            return;
350        }
351
352        const char *b;
353        if (((b = strnstr(cp, len, suspendStr)))
354                && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
355            len -= b - cp;
356            calculateCorrection(now, b, len);
357        } else if (((b = strnstr(cp, len, resumeStr)))
358                && ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) {
359            len -= b - cp;
360            calculateCorrection(now, b, len);
361        } else if (((b = strnstr(cp, len, healthd)))
362                && ((size_t)((b += sizeof(healthd) - 1) - cp) < len)
363                && ((b = strnstr(b, len -= b - cp, battery)))
364                && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) {
365            // NB: healthd is roughly 150us late, so we use it instead to
366            //     trigger a check for ntp-induced or hardware clock drift.
367            log_time real(CLOCK_REALTIME);
368            log_time mono(CLOCK_MONOTONIC);
369            correction = (real < mono) ? log_time::EPOCH : (real - mono);
370        } else if (((b = strnstr(cp, len, suspendedStr)))
371                && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
372            len -= b - cp;
373            log_time real;
374            char *endp;
375            real.tv_sec = strtol(b, &endp, 10);
376            if ((*endp == '.') && ((size_t)(endp - b) < len)) {
377                unsigned long multiplier = NS_PER_SEC;
378                real.tv_nsec = 0;
379                len -= endp - b;
380                while (--len && isdigit(*++endp) && (multiplier /= 10)) {
381                    real.tv_nsec += (*endp - '0') * multiplier;
382                }
383                if (reverse) {
384                    if (real > correction) {
385                        correction = log_time::EPOCH;
386                    } else {
387                        correction -= real;
388                    }
389                } else {
390                    correction += real;
391                }
392            }
393        }
394
395        convertMonotonicToReal(now);
396    } else {
397        if (isMonotonic()) {
398            now = log_time(CLOCK_MONOTONIC);
399        } else {
400            now = log_time(CLOCK_REALTIME);
401        }
402    }
403}
404
405pid_t LogKlog::sniffPid(const char **buf, size_t len) {
406    const char *cp = *buf;
407    // HTC kernels with modified printk "c0   1648 "
408    if ((len > 9) &&
409            (cp[0] == 'c') &&
410            isdigit(cp[1]) &&
411            (isdigit(cp[2]) || (cp[2] == ' ')) &&
412            (cp[3] == ' ')) {
413        bool gotDigit = false;
414        int i;
415        for (i = 4; i < 9; ++i) {
416            if (isdigit(cp[i])) {
417                gotDigit = true;
418            } else if (gotDigit || (cp[i] != ' ')) {
419                break;
420            }
421        }
422        if ((i == 9) && (cp[i] == ' ')) {
423            int pid = 0;
424            char dummy;
425            if (sscanf(cp + 4, "%d%c", &pid, &dummy) == 2) {
426                *buf = cp + 10; // skip-it-all
427                return pid;
428            }
429        }
430    }
431    while (len) {
432        // Mediatek kernels with modified printk
433        if (*cp == '[') {
434            int pid = 0;
435            char dummy;
436            if (sscanf(cp, "[%d:%*[a-z_./0-9:A-Z]]%c", &pid, &dummy) == 2) {
437                return pid;
438            }
439            break; // Only the first one
440        }
441        ++cp;
442        --len;
443    }
444    return 0;
445}
446
447// kernel log prefix, convert to a kernel log priority number
448static int parseKernelPrio(const char **buf, size_t len) {
449    int pri = LOG_USER | LOG_INFO;
450    const char *cp = *buf;
451    if (len && (*cp == '<')) {
452        pri = 0;
453        while(--len && isdigit(*++cp)) {
454            pri = (pri * 10) + *cp - '0';
455        }
456        if (len && (*cp == '>')) {
457            ++cp;
458        } else {
459            cp = *buf;
460            pri = LOG_USER | LOG_INFO;
461        }
462        *buf = cp;
463    }
464    return pri;
465}
466
467// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
468// compensated start time.
469void LogKlog::synchronize(const char *buf, size_t len) {
470    const char *cp = strnstr(buf, len, suspendStr);
471    if (!cp) {
472        cp = strnstr(buf, len, resumeStr);
473        if (!cp) {
474            return;
475        }
476    } else {
477        const char *rp = strnstr(buf, len, resumeStr);
478        if (rp && (rp < cp)) {
479            cp = rp;
480        }
481    }
482
483    do {
484        --cp;
485    } while ((cp > buf) && (*cp != '\n'));
486    if (*cp == '\n') {
487        ++cp;
488    }
489    parseKernelPrio(&cp, len - (cp - buf));
490
491    log_time now;
492    sniffTime(now, &cp, len - (cp - buf), true);
493
494    const char *suspended = strnstr(buf, len, suspendedStr);
495    if (!suspended || (suspended > cp)) {
496        return;
497    }
498    cp = suspended;
499
500    do {
501        --cp;
502    } while ((cp > buf) && (*cp != '\n'));
503    if (*cp == '\n') {
504        ++cp;
505    }
506    parseKernelPrio(&cp, len - (cp - buf));
507
508    sniffTime(now, &cp, len - (cp - buf), true);
509}
510
511// Convert kernel log priority number into an Android Logger priority number
512static int convertKernelPrioToAndroidPrio(int pri) {
513    switch(pri & LOG_PRIMASK) {
514    case LOG_EMERG:
515        // FALLTHRU
516    case LOG_ALERT:
517        // FALLTHRU
518    case LOG_CRIT:
519        return ANDROID_LOG_FATAL;
520
521    case LOG_ERR:
522        return ANDROID_LOG_ERROR;
523
524    case LOG_WARNING:
525        return ANDROID_LOG_WARN;
526
527    default:
528        // FALLTHRU
529    case LOG_NOTICE:
530        // FALLTHRU
531    case LOG_INFO:
532        break;
533
534    case LOG_DEBUG:
535        return ANDROID_LOG_DEBUG;
536    }
537
538    return ANDROID_LOG_INFO;
539}
540
541static const char *strnrchr(const char *s, size_t len, char c) {
542  const char *save = NULL;
543  for (;len; ++s, len--) {
544    if (*s == c) {
545      save = s;
546    }
547  }
548  return save;
549}
550
551//
552// log a message into the kernel log buffer
553//
554// Filter rules to parse <PRI> <TIME> <tag> and <message> in order for
555// them to appear correct in the logcat output:
556//
557// LOG_KERN (0):
558// <PRI>[<TIME>] <tag> ":" <message>
559// <PRI>[<TIME>] <tag> <tag> ":" <message>
560// <PRI>[<TIME>] <tag> <tag>_work ":" <message>
561// <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message>
562// <PRI>[<TIME>] <tag> '<tag><num>' ":" <message>
563// <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message>
564// (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message>
565// <PRI>[<TIME>] "[INFO]"<tag> : <message>
566// <PRI>[<TIME>] "------------[ cut here ]------------"   (?)
567// <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---"   (?)
568// LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS
569// LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP:
570// <PRI+TAG>[<TIME>] (see sys/syslog.h)
571// Observe:
572//  Minimum tag length = 3   NB: drops things like r5:c00bbadf, but allow PM:
573//  Maximum tag words = 2
574//  Maximum tag length = 16  NB: we are thinking of how ugly logcat can get.
575//  Not a Tag if there is no message content.
576//  leading additional spaces means no tag, inherit last tag.
577//  Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:"
578// Drop:
579//  empty messages
580//  messages with ' audit(' in them if auditd is running
581//  logd.klogd:
582// return -1 if message logd.klogd: <signature>
583//
584int LogKlog::log(const char *buf, size_t len) {
585    if (auditd && strnstr(buf, len, " audit(")) {
586        return 0;
587    }
588
589    const char *p = buf;
590    int pri = parseKernelPrio(&p, len);
591
592    log_time now;
593    sniffTime(now, &p, len - (p - buf), false);
594
595    // sniff for start marker
596    const char klogd_message[] = "logd.klogd: ";
597    const char *start = strnstr(p, len - (p - buf), klogd_message);
598    if (start) {
599        uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10);
600        if (sig == signature.nsec()) {
601            if (initialized) {
602                enableLogging = true;
603            } else {
604                enableLogging = false;
605            }
606            return -1;
607        }
608        return 0;
609    }
610
611    if (!enableLogging) {
612        return 0;
613    }
614
615    // Parse pid, tid and uid
616    const pid_t pid = sniffPid(&p, len - (p - buf));
617    const pid_t tid = pid;
618    uid_t uid = AID_ROOT;
619    if (pid) {
620        logbuf->lock();
621        uid = logbuf->pidToUid(pid);
622        logbuf->unlock();
623    }
624
625    // Parse (rules at top) to pull out a tag from the incoming kernel message.
626    // Some may view the following as an ugly heuristic, the desire is to
627    // beautify the kernel logs into an Android Logging format; the goal is
628    // admirable but costly.
629    while ((p < &buf[len]) && (isspace(*p) || !*p)) {
630        ++p;
631    }
632    if (p >= &buf[len]) { // timestamp, no content
633        return 0;
634    }
635    start = p;
636    const char *tag = "";
637    const char *etag = tag;
638    size_t taglen = len - (p - buf);
639    const char *bt = p;
640
641    static const char infoBrace[] = "[INFO]";
642    static const size_t infoBraceLen = strlen(infoBrace);
643    if ((taglen >= infoBraceLen) && !fast<strncmp>(p, infoBrace, infoBraceLen)) {
644        // <PRI>[<TIME>] "[INFO]"<tag> ":" message
645        bt = p + infoBraceLen;
646        taglen -= infoBraceLen;
647    }
648
649    const char *et;
650    for (et = bt; taglen && *et && (*et != ':') && !isspace(*et); ++et, --taglen) {
651       // skip ':' within [ ... ]
652       if (*et == '[') {
653           while (taglen && *et && *et != ']') {
654               ++et;
655               --taglen;
656           }
657           if (!taglen) {
658               break;
659           }
660       }
661    }
662    const char *cp;
663    for (cp = et; taglen && isspace(*cp); ++cp, --taglen);
664
665    // Validate tag
666    size_t size = et - bt;
667    if (taglen && size) {
668        if (*cp == ':') {
669            // ToDo: handle case insensitive colon separated logging stutter:
670            //       <tag> : <tag>: ...
671
672            // One Word
673            tag = bt;
674            etag = et;
675            p = cp + 1;
676        } else if ((taglen > size) && (tolower(*bt) == tolower(*cp))) {
677            // clean up any tag stutter
678            if (!fast<strncasecmp>(bt + 1, cp + 1, size - 1)) { // no match
679                // <PRI>[<TIME>] <tag> <tag> : message
680                // <PRI>[<TIME>] <tag> <tag>: message
681                // <PRI>[<TIME>] <tag> '<tag>.<num>' : message
682                // <PRI>[<TIME>] <tag> '<tag><num>' : message
683                // <PRI>[<TIME>] <tag> '<tag><stuff>' : message
684                const char *b = cp;
685                cp += size;
686                taglen -= size;
687                while (--taglen && !isspace(*++cp) && (*cp != ':'));
688                const char *e;
689                for (e = cp; taglen && isspace(*cp); ++cp, --taglen);
690                if (taglen && (*cp == ':')) {
691                    tag = b;
692                    etag = e;
693                    p = cp + 1;
694                }
695            } else {
696                // what about <PRI>[<TIME>] <tag>_host '<tag><stuff>' : message
697                static const char host[] = "_host";
698                static const size_t hostlen = strlen(host);
699                if ((size > hostlen) &&
700                        !fast<strncmp>(bt + size - hostlen, host, hostlen) &&
701                        !fast<strncmp>(bt + 1, cp + 1, size - hostlen - 1)) {
702                    const char *b = cp;
703                    cp += size - hostlen;
704                    taglen -= size - hostlen;
705                    if (*cp == '.') {
706                        while (--taglen && !isspace(*++cp) && (*cp != ':'));
707                        const char *e;
708                        for (e = cp; taglen && isspace(*cp); ++cp, --taglen);
709                        if (taglen && (*cp == ':')) {
710                            tag = b;
711                            etag = e;
712                            p = cp + 1;
713                        }
714                    }
715                } else {
716                    goto twoWord;
717                }
718            }
719        } else {
720            // <PRI>[<TIME>] <tag> <stuff>' : message
721twoWord:    while (--taglen && !isspace(*++cp) && (*cp != ':'));
722            const char *e;
723            for (e = cp; taglen && isspace(*cp); ++cp, --taglen);
724            // Two words
725            if (taglen && (*cp == ':')) {
726                tag = bt;
727                etag = e;
728                p = cp + 1;
729            }
730        }
731    } // else no tag
732
733    static const char cpu[] = "CPU";
734    static const size_t cpuLen = strlen(cpu);
735    static const char warning[] = "WARNING";
736    static const size_t warningLen = strlen(warning);
737    static const char error[] = "ERROR";
738    static const size_t errorLen = strlen(error);
739    static const char info[] = "INFO";
740    static const size_t infoLen = strlen(info);
741
742    size = etag - tag;
743    if ((size <= 1)
744        // register names like x9
745            || ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1])))
746        // register names like x18 but not driver names like en0
747            || ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2])))
748        // blacklist
749            || ((size == cpuLen) && !fast<strncmp>(tag, cpu, cpuLen))
750            || ((size == warningLen) && !fast<strncasecmp>(tag, warning, warningLen))
751            || ((size == errorLen) && !fast<strncasecmp>(tag, error, errorLen))
752            || ((size == infoLen) && !fast<strncasecmp>(tag, info, infoLen))) {
753        p = start;
754        etag = tag = "";
755    }
756
757    // Suppress additional stutter in tag:
758    //   eg: [143:healthd]healthd -> [143:healthd]
759    taglen = etag - tag;
760    // Mediatek-special printk induced stutter
761    const char *mp = strnrchr(tag, ']', taglen);
762    if (mp && (++mp < etag)) {
763        size_t s = etag - mp;
764        if (((s + s) < taglen) && !fast<memcmp>(mp, mp - 1 - s, s)) {
765            taglen = mp - tag;
766        }
767    }
768    // Deal with sloppy and simplistic harmless p = cp + 1 etc above.
769    if (len < (size_t)(p - buf)) {
770        p = &buf[len];
771    }
772    // skip leading space
773    while ((p < &buf[len]) && (isspace(*p) || !*p)) {
774        ++p;
775    }
776    // truncate trailing space or nuls
777    size_t b = len - (p - buf);
778    while (b && (isspace(p[b-1]) || !p[b-1])) {
779        --b;
780    }
781    // trick ... allow tag with empty content to be logged. log() drops empty
782    if (!b && taglen) {
783        p = " ";
784        b = 1;
785    }
786    // paranoid sanity check, can not happen ...
787    if (b > LOGGER_ENTRY_MAX_PAYLOAD) {
788        b = LOGGER_ENTRY_MAX_PAYLOAD;
789    }
790    if (taglen > LOGGER_ENTRY_MAX_PAYLOAD) {
791        taglen = LOGGER_ENTRY_MAX_PAYLOAD;
792    }
793    // calculate buffer copy requirements
794    size_t n = 1 + taglen + 1 + b + 1;
795    // paranoid sanity check, first two just can not happen ...
796    if ((taglen > n) || (b > n) || (n > USHRT_MAX)) {
797        return -EINVAL;
798    }
799
800    // Careful.
801    // We are using the stack to house the log buffer for speed reasons.
802    // If we malloc'd this buffer, we could get away without n's USHRT_MAX
803    // test above, but we would then required a max(n, USHRT_MAX) as
804    // truncating length argument to logbuf->log() below. Gain is protection
805    // of stack sanity and speedup, loss is truncated long-line content.
806    char newstr[n];
807    char *np = newstr;
808
809    // Convert priority into single-byte Android logger priority
810    *np = convertKernelPrioToAndroidPrio(pri);
811    ++np;
812
813    // Copy parsed tag following priority
814    memcpy(np, tag, taglen);
815    np += taglen;
816    *np = '\0';
817    ++np;
818
819    // Copy main message to the remainder
820    memcpy(np, p, b);
821    np[b] = '\0';
822
823    if (!isMonotonic()) {
824        // Watch out for singular race conditions with timezone causing near
825        // integer quarter-hour jumps in the time and compensate accordingly.
826        // Entries will be temporal within near_seconds * 2. b/21868540
827        static uint32_t vote_time[3];
828        vote_time[2] = vote_time[1];
829        vote_time[1] = vote_time[0];
830        vote_time[0] = now.tv_sec;
831
832        if (vote_time[1] && vote_time[2]) {
833            static const unsigned near_seconds = 10;
834            static const unsigned timezones_seconds = 900;
835            int diff0 = (vote_time[0] - vote_time[1]) / near_seconds;
836            unsigned abs0 = (diff0 < 0) ? -diff0 : diff0;
837            int diff1 = (vote_time[1] - vote_time[2]) / near_seconds;
838            unsigned abs1 = (diff1 < 0) ? -diff1 : diff1;
839            if ((abs1 <= 1) && // last two were in agreement on timezone
840                    ((abs0 + 1) % (timezones_seconds / near_seconds)) <= 2) {
841                abs0 = (abs0 + 1) / (timezones_seconds / near_seconds) *
842                                     timezones_seconds;
843                now.tv_sec -= (diff0 < 0) ? -abs0 : abs0;
844            }
845        }
846    }
847
848    // Log message
849    int rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr,
850                         (unsigned short) n);
851
852    // notify readers
853    if (!rc) {
854        reader->notifyNewLog();
855    }
856
857    return rc;
858}
859