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