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
38 static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
39
40 // List of the _only_ needles we supply here to android::strnstr
41 static const char suspendStr[] = "PM: suspend entry ";
42 static const char resumeStr[] = "PM: suspend exit ";
43 static const char suspendedStr[] = "Suspended for ";
44 static const char healthdStr[] = "healthd";
45 static const char batteryStr[] = ": battery ";
46 static const char auditStr[] = " audit(";
47 static 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 '>'
is_prio(char * s,ssize_t len)52 static 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 ']'
is_timestamp(char * s,ssize_t len)65 static 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
log_strntok_r(char * s,ssize_t & len,char * & last,ssize_t & sublen)99 char* 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
200 log_time LogKlog::correction = (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTONIC))
201 ? log_time(log_time::EPOCH)
202 : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC));
203
LogKlog(LogBuffer * buf,LogReader * reader,int fdWrite,int fdRead,bool auditd)204 LogKlog::LogKlog(LogBuffer* buf, LogReader* reader, int fdWrite, int fdRead,
205 bool auditd)
206 : SocketListener(fdRead, false),
207 logbuf(buf),
208 reader(reader),
209 signature(CLOCK_MONOTONIC),
210 initialized(false),
211 enableLogging(true),
212 auditd(auditd) {
213 static const char klogd_message[] = "%s%s%" PRIu64 "\n";
214 char buffer[strlen(priority_message) + strlen(klogdStr) +
215 strlen(klogd_message) + 20];
216 snprintf(buffer, sizeof(buffer), klogd_message, priority_message, klogdStr,
217 signature.nsec());
218 write(fdWrite, buffer, strlen(buffer));
219 }
220
onDataAvailable(SocketClient * cli)221 bool LogKlog::onDataAvailable(SocketClient* cli) {
222 if (!initialized) {
223 prctl(PR_SET_NAME, "logd.klogd");
224 initialized = true;
225 enableLogging = false;
226 }
227
228 char buffer[LOGGER_ENTRY_MAX_PAYLOAD];
229 ssize_t len = 0;
230
231 for (;;) {
232 ssize_t retval = 0;
233 if (len < (ssize_t)(sizeof(buffer) - 1)) {
234 retval =
235 read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len);
236 }
237 if ((retval == 0) && (len <= 0)) {
238 break;
239 }
240 if (retval < 0) {
241 return false;
242 }
243 len += retval;
244 bool full = len == (sizeof(buffer) - 1);
245 char* ep = buffer + len;
246 *ep = '\0';
247 ssize_t sublen;
248 for (char *ptr = nullptr, *tok = buffer;
249 !!(tok = android::log_strntok_r(tok, len, ptr, sublen));
250 tok = nullptr) {
251 if (((tok + sublen) >= ep) && (retval != 0) && full) {
252 if (sublen > 0) memmove(buffer, tok, sublen);
253 len = sublen;
254 break;
255 }
256 if ((sublen > 0) && *tok) {
257 log(tok, sublen);
258 }
259 }
260 }
261
262 return true;
263 }
264
calculateCorrection(const log_time & monotonic,const char * real_string,ssize_t len)265 void LogKlog::calculateCorrection(const log_time& monotonic,
266 const char* real_string, ssize_t len) {
267 static const char real_format[] = "%Y-%m-%d %H:%M:%S.%09q UTC";
268 if (len < (ssize_t)(strlen(real_format) + 5)) return;
269
270 log_time real(log_time::EPOCH);
271 const char* ep = real.strptime(real_string, real_format);
272 if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) {
273 return;
274 }
275 // kernel report UTC, log_time::strptime is localtime from calendar.
276 // Bionic and liblog strptime does not support %z or %Z to pick up
277 // timezone so we are calculating our own correction.
278 time_t now = real.tv_sec;
279 struct tm tm;
280 memset(&tm, 0, sizeof(tm));
281 tm.tm_isdst = -1;
282 localtime_r(&now, &tm);
283 if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > (long)real.tv_sec)) {
284 real = log_time(log_time::EPOCH);
285 } else {
286 real.tv_sec += tm.tm_gmtoff;
287 }
288 if (monotonic > real) {
289 correction = log_time(log_time::EPOCH);
290 } else {
291 correction = real - monotonic;
292 }
293 }
294
sniffTime(const char * & buf,ssize_t len,bool reverse)295 log_time LogKlog::sniffTime(const char*& buf, ssize_t len, bool reverse) {
296 log_time now(log_time::EPOCH);
297 if (len <= 0) return now;
298
299 const char* cp = nullptr;
300 if ((len > 10) && (*buf == '[')) {
301 cp = now.strptime(buf, "[ %s.%q]"); // can index beyond buffer bounds
302 if (cp && (cp > &buf[len - 1])) cp = nullptr;
303 }
304 if (cp) {
305 len -= cp - buf;
306 if ((len > 0) && isspace(*cp)) {
307 ++cp;
308 --len;
309 }
310 buf = cp;
311
312 if (isMonotonic()) return now;
313
314 const char* b;
315 if (((b = android::strnstr(cp, len, suspendStr))) &&
316 (((b += strlen(suspendStr)) - cp) < len)) {
317 len -= b - cp;
318 calculateCorrection(now, b, len);
319 } else if (((b = android::strnstr(cp, len, resumeStr))) &&
320 (((b += strlen(resumeStr)) - cp) < len)) {
321 len -= b - cp;
322 calculateCorrection(now, b, len);
323 } else if (((b = android::strnstr(cp, len, healthdStr))) &&
324 (((b += strlen(healthdStr)) - cp) < len) &&
325 ((b = android::strnstr(b, len -= b - cp, batteryStr))) &&
326 (((b += strlen(batteryStr)) - cp) < len)) {
327 // NB: healthd is roughly 150us late, so we use it instead to
328 // trigger a check for ntp-induced or hardware clock drift.
329 log_time real(CLOCK_REALTIME);
330 log_time mono(CLOCK_MONOTONIC);
331 correction = (real < mono) ? log_time(log_time::EPOCH) : (real - mono);
332 } else if (((b = android::strnstr(cp, len, suspendedStr))) &&
333 (((b += strlen(suspendStr)) - cp) < len)) {
334 len -= b - cp;
335 log_time real(log_time::EPOCH);
336 char* endp;
337 real.tv_sec = strtol(b, &endp, 10);
338 if ((*endp == '.') && ((endp - b) < len)) {
339 unsigned long multiplier = NS_PER_SEC;
340 real.tv_nsec = 0;
341 len -= endp - b;
342 while (--len && isdigit(*++endp) && (multiplier /= 10)) {
343 real.tv_nsec += (*endp - '0') * multiplier;
344 }
345 if (reverse) {
346 if (real > correction) {
347 correction = log_time(log_time::EPOCH);
348 } else {
349 correction -= real;
350 }
351 } else {
352 correction += real;
353 }
354 }
355 }
356
357 convertMonotonicToReal(now);
358 } else {
359 if (isMonotonic()) {
360 now = log_time(CLOCK_MONOTONIC);
361 } else {
362 now = log_time(CLOCK_REALTIME);
363 }
364 }
365 return now;
366 }
367
sniffPid(const char * & buf,ssize_t len)368 pid_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
parseKernelPrio(const char * & buf,ssize_t len)415 static 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.
synchronize(const char * buf,ssize_t len)436 void 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 = sniffTime(cp, len - (cp - buf), true);
455
456 const char* suspended = android::strnstr(buf, len, suspendedStr);
457 if (!suspended || (suspended > cp)) {
458 return;
459 }
460 cp = suspended;
461
462 do {
463 --cp;
464 } while ((cp > buf) && (*cp != '\n'));
465 if (*cp == '\n') {
466 ++cp;
467 }
468 parseKernelPrio(cp, len - (cp - buf));
469
470 sniffTime(cp, len - (cp - buf), true);
471 }
472
473 // Convert kernel log priority number into an Android Logger priority number
convertKernelPrioToAndroidPrio(int pri)474 static int convertKernelPrioToAndroidPrio(int pri) {
475 switch (pri & LOG_PRIMASK) {
476 case LOG_EMERG:
477 case LOG_ALERT:
478 case LOG_CRIT:
479 return ANDROID_LOG_FATAL;
480
481 case LOG_ERR:
482 return ANDROID_LOG_ERROR;
483
484 case LOG_WARNING:
485 return ANDROID_LOG_WARN;
486
487 default:
488 case LOG_NOTICE:
489 case LOG_INFO:
490 break;
491
492 case LOG_DEBUG:
493 return ANDROID_LOG_DEBUG;
494 }
495
496 return ANDROID_LOG_INFO;
497 }
498
strnrchr(const char * s,ssize_t len,char c)499 static const char* strnrchr(const char* s, ssize_t len, char c) {
500 const char* save = nullptr;
501 for (; len > 0; ++s, len--) {
502 if (*s == c) {
503 save = s;
504 }
505 }
506 return save;
507 }
508
509 //
510 // log a message into the kernel log buffer
511 //
512 // Filter rules to parse <PRI> <TIME> <tag> and <message> in order for
513 // them to appear correct in the logcat output:
514 //
515 // LOG_KERN (0):
516 // <PRI>[<TIME>] <tag> ":" <message>
517 // <PRI>[<TIME>] <tag> <tag> ":" <message>
518 // <PRI>[<TIME>] <tag> <tag>_work ":" <message>
519 // <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message>
520 // <PRI>[<TIME>] <tag> '<tag><num>' ":" <message>
521 // <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message>
522 // (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message>
523 // <PRI>[<TIME>] "[INFO]"<tag> : <message>
524 // <PRI>[<TIME>] "------------[ cut here ]------------" (?)
525 // <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---" (?)
526 // LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS
527 // LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP:
528 // <PRI+TAG>[<TIME>] (see sys/syslog.h)
529 // Observe:
530 // Minimum tag length = 3 NB: drops things like r5:c00bbadf, but allow PM:
531 // Maximum tag words = 2
532 // Maximum tag length = 16 NB: we are thinking of how ugly logcat can get.
533 // Not a Tag if there is no message content.
534 // leading additional spaces means no tag, inherit last tag.
535 // Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:"
536 // Drop:
537 // empty messages
538 // messages with ' audit(' in them if auditd is running
539 // logd.klogd:
540 // return -1 if message logd.klogd: <signature>
541 //
log(const char * buf,ssize_t len)542 int LogKlog::log(const char* buf, ssize_t len) {
543 if (auditd && android::strnstr(buf, len, auditStr)) {
544 return 0;
545 }
546
547 const char* p = buf;
548 int pri = parseKernelPrio(p, len);
549
550 log_time now = sniffTime(p, len - (p - buf), false);
551
552 // sniff for start marker
553 const char* start = android::strnstr(p, len - (p - buf), klogdStr);
554 if (start) {
555 uint64_t sig = strtoll(start + strlen(klogdStr), nullptr, 10);
556 if (sig == signature.nsec()) {
557 if (initialized) {
558 enableLogging = true;
559 } else {
560 enableLogging = false;
561 }
562 return -1;
563 }
564 return 0;
565 }
566
567 if (!enableLogging) {
568 return 0;
569 }
570
571 // Parse pid, tid and uid
572 const pid_t pid = sniffPid(p, len - (p - buf));
573 const pid_t tid = pid;
574 uid_t uid = AID_ROOT;
575 if (pid) {
576 logbuf->wrlock();
577 uid = logbuf->pidToUid(pid);
578 logbuf->unlock();
579 }
580
581 // Parse (rules at top) to pull out a tag from the incoming kernel message.
582 // Some may view the following as an ugly heuristic, the desire is to
583 // beautify the kernel logs into an Android Logging format; the goal is
584 // admirable but costly.
585 while ((p < &buf[len]) && (isspace(*p) || !*p)) {
586 ++p;
587 }
588 if (p >= &buf[len]) { // timestamp, no content
589 return 0;
590 }
591 start = p;
592 const char* tag = "";
593 const char* etag = tag;
594 ssize_t taglen = len - (p - buf);
595 const char* bt = p;
596
597 static const char infoBrace[] = "[INFO]";
598 static const ssize_t infoBraceLen = strlen(infoBrace);
599 if ((taglen >= infoBraceLen) &&
600 !fastcmp<strncmp>(p, infoBrace, infoBraceLen)) {
601 // <PRI>[<TIME>] "[INFO]"<tag> ":" message
602 bt = p + infoBraceLen;
603 taglen -= infoBraceLen;
604 }
605
606 const char* et;
607 for (et = bt; (taglen > 0) && *et && (*et != ':') && !isspace(*et);
608 ++et, --taglen) {
609 // skip ':' within [ ... ]
610 if (*et == '[') {
611 while ((taglen > 0) && *et && *et != ']') {
612 ++et;
613 --taglen;
614 }
615 if (taglen <= 0) {
616 break;
617 }
618 }
619 }
620 const char* cp;
621 for (cp = et; (taglen > 0) && isspace(*cp); ++cp, --taglen) {
622 }
623
624 // Validate tag
625 ssize_t size = et - bt;
626 if ((taglen > 0) && (size > 0)) {
627 if (*cp == ':') {
628 // ToDo: handle case insensitive colon separated logging stutter:
629 // <tag> : <tag>: ...
630
631 // One Word
632 tag = bt;
633 etag = et;
634 p = cp + 1;
635 } else if ((taglen > size) && (tolower(*bt) == tolower(*cp))) {
636 // clean up any tag stutter
637 if (!fastcmp<strncasecmp>(bt + 1, cp + 1, size - 1)) { // no match
638 // <PRI>[<TIME>] <tag> <tag> : message
639 // <PRI>[<TIME>] <tag> <tag>: message
640 // <PRI>[<TIME>] <tag> '<tag>.<num>' : message
641 // <PRI>[<TIME>] <tag> '<tag><num>' : message
642 // <PRI>[<TIME>] <tag> '<tag><stuff>' : message
643 const char* b = cp;
644 cp += size;
645 taglen -= size;
646 while ((--taglen > 0) && !isspace(*++cp) && (*cp != ':')) {
647 }
648 const char* e;
649 for (e = cp; (taglen > 0) && isspace(*cp); ++cp, --taglen) {
650 }
651 if ((taglen > 0) && (*cp == ':')) {
652 tag = b;
653 etag = e;
654 p = cp + 1;
655 }
656 } else {
657 // what about <PRI>[<TIME>] <tag>_host '<tag><stuff>' : message
658 static const char host[] = "_host";
659 static const ssize_t hostlen = strlen(host);
660 if ((size > hostlen) &&
661 !fastcmp<strncmp>(bt + size - hostlen, host, hostlen) &&
662 !fastcmp<strncmp>(bt + 1, cp + 1, size - hostlen - 1)) {
663 const char* b = cp;
664 cp += size - hostlen;
665 taglen -= size - hostlen;
666 if (*cp == '.') {
667 while ((--taglen > 0) && !isspace(*++cp) &&
668 (*cp != ':')) {
669 }
670 const char* e;
671 for (e = cp; (taglen > 0) && isspace(*cp);
672 ++cp, --taglen) {
673 }
674 if ((taglen > 0) && (*cp == ':')) {
675 tag = b;
676 etag = e;
677 p = cp + 1;
678 }
679 }
680 } else {
681 goto twoWord;
682 }
683 }
684 } else {
685 // <PRI>[<TIME>] <tag> <stuff>' : message
686 twoWord:
687 while ((--taglen > 0) && !isspace(*++cp) && (*cp != ':')) {
688 }
689 const char* e;
690 for (e = cp; (taglen > 0) && isspace(*cp); ++cp, --taglen) {
691 }
692 // Two words
693 if ((taglen > 0) && (*cp == ':')) {
694 tag = bt;
695 etag = e;
696 p = cp + 1;
697 }
698 }
699 } // else no tag
700
701 static const char cpu[] = "CPU";
702 static const ssize_t cpuLen = strlen(cpu);
703 static const char warning[] = "WARNING";
704 static const ssize_t warningLen = strlen(warning);
705 static const char error[] = "ERROR";
706 static const ssize_t errorLen = strlen(error);
707 static const char info[] = "INFO";
708 static const ssize_t infoLen = strlen(info);
709
710 size = etag - tag;
711 if ((size <= 1) ||
712 // register names like x9
713 ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1]))) ||
714 // register names like x18 but not driver names like en0
715 ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2]))) ||
716 // blacklist
717 ((size == cpuLen) && !fastcmp<strncmp>(tag, cpu, cpuLen)) ||
718 ((size == warningLen) &&
719 !fastcmp<strncasecmp>(tag, warning, warningLen)) ||
720 ((size == errorLen) && !fastcmp<strncasecmp>(tag, error, errorLen)) ||
721 ((size == infoLen) && !fastcmp<strncasecmp>(tag, info, infoLen))) {
722 p = start;
723 etag = tag = "";
724 }
725
726 // Suppress additional stutter in tag:
727 // eg: [143:healthd]healthd -> [143:healthd]
728 taglen = etag - tag;
729 // Mediatek-special printk induced stutter
730 const char* mp = strnrchr(tag, taglen, ']');
731 if (mp && (++mp < etag)) {
732 ssize_t s = etag - mp;
733 if (((s + s) < taglen) && !fastcmp<memcmp>(mp, mp - 1 - s, s)) {
734 taglen = mp - tag;
735 }
736 }
737 // Deal with sloppy and simplistic harmless p = cp + 1 etc above.
738 if (len < (p - buf)) {
739 p = &buf[len];
740 }
741 // skip leading space
742 while ((p < &buf[len]) && (isspace(*p) || !*p)) {
743 ++p;
744 }
745 // truncate trailing space or nuls
746 ssize_t b = len - (p - buf);
747 while ((b > 0) && (isspace(p[b - 1]) || !p[b - 1])) {
748 --b;
749 }
750 // trick ... allow tag with empty content to be logged. log() drops empty
751 if ((b <= 0) && (taglen > 0)) {
752 p = " ";
753 b = 1;
754 }
755 // paranoid sanity check, can not happen ...
756 if (b > LOGGER_ENTRY_MAX_PAYLOAD) {
757 b = LOGGER_ENTRY_MAX_PAYLOAD;
758 }
759 if (taglen > LOGGER_ENTRY_MAX_PAYLOAD) {
760 taglen = LOGGER_ENTRY_MAX_PAYLOAD;
761 }
762 // calculate buffer copy requirements
763 ssize_t n = 1 + taglen + 1 + b + 1;
764 // paranoid sanity check, first two just can not happen ...
765 if ((taglen > n) || (b > n) || (n > (ssize_t)USHRT_MAX) || (n <= 0)) {
766 return -EINVAL;
767 }
768
769 // Careful.
770 // We are using the stack to house the log buffer for speed reasons.
771 // If we malloc'd this buffer, we could get away without n's USHRT_MAX
772 // test above, but we would then required a max(n, USHRT_MAX) as
773 // truncating length argument to logbuf->log() below. Gain is protection
774 // of stack sanity and speedup, loss is truncated long-line content.
775 char newstr[n];
776 char* np = newstr;
777
778 // Convert priority into single-byte Android logger priority
779 *np = convertKernelPrioToAndroidPrio(pri);
780 ++np;
781
782 // Copy parsed tag following priority
783 memcpy(np, tag, taglen);
784 np += taglen;
785 *np = '\0';
786 ++np;
787
788 // Copy main message to the remainder
789 memcpy(np, p, b);
790 np[b] = '\0';
791
792 if (!isMonotonic()) {
793 // Watch out for singular race conditions with timezone causing near
794 // integer quarter-hour jumps in the time and compensate accordingly.
795 // Entries will be temporal within near_seconds * 2. b/21868540
796 static uint32_t vote_time[3];
797 vote_time[2] = vote_time[1];
798 vote_time[1] = vote_time[0];
799 vote_time[0] = now.tv_sec;
800
801 if (vote_time[1] && vote_time[2]) {
802 static const unsigned near_seconds = 10;
803 static const unsigned timezones_seconds = 900;
804 int diff0 = (vote_time[0] - vote_time[1]) / near_seconds;
805 unsigned abs0 = (diff0 < 0) ? -diff0 : diff0;
806 int diff1 = (vote_time[1] - vote_time[2]) / near_seconds;
807 unsigned abs1 = (diff1 < 0) ? -diff1 : diff1;
808 if ((abs1 <= 1) && // last two were in agreement on timezone
809 ((abs0 + 1) % (timezones_seconds / near_seconds)) <= 2) {
810 abs0 = (abs0 + 1) / (timezones_seconds / near_seconds) *
811 timezones_seconds;
812 now.tv_sec -= (diff0 < 0) ? -abs0 : abs0;
813 }
814 }
815 }
816
817 // Log message
818 int rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr, (uint16_t)n);
819
820 // notify readers
821 if (rc > 0) {
822 reader->notifyNewLog(static_cast<log_mask_t>(1 << LOG_ID_KERNEL));
823 }
824
825 return rc;
826 }
827