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
41 static 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 '>'
is_prio(char * s,size_t len)46 static 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 ']'
is_timestamp(char * s,size_t len)63 static 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
log_strntok_r(char * s,size_t * len,char ** last,size_t * sublen)98 char *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
213 log_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
LogKlog(LogBuffer * buf,LogReader * reader,int fdWrite,int fdRead,bool auditd)218 LogKlog::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
onDataAvailable(SocketClient * cli)233 bool 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
calculateCorrection(const log_time & monotonic,const char * real_string,size_t len)277 void 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
305 static const char suspendStr[] = "PM: suspend entry ";
306 static const char resumeStr[] = "PM: suspend exit ";
307 static const char suspendedStr[] = "Suspended for ";
308
strnstr(const char * s,size_t len,const char * needle)309 static 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
sniffTime(log_time & now,const char ** buf,size_t len,bool reverse)330 void 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
sniffPid(const char ** buf,size_t len)405 pid_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
parseKernelPrio(const char ** buf,size_t len)448 static 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.
synchronize(const char * buf,size_t len)469 void 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
convertKernelPrioToAndroidPrio(int pri)512 static 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
strnrchr(const char * s,size_t len,char c)541 static 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 //
log(const char * buf,size_t len)584 int 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
721 twoWord: 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