blob: eff26f58e9bfb06f1562924d29601e3b8506c6e1 [file] [log] [blame]
Mark Salyzynae4d9282014-10-15 08:49:39 -07001/*
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 <sys/prctl.h>
24#include <sys/uio.h>
25#include <syslog.h>
26
27#include <log/logger.h>
28
29#include "LogKlog.h"
30
31#define KMSG_PRIORITY(PRI) \
32 '<', \
33 '0' + (LOG_SYSLOG | (PRI)) / 10, \
34 '0' + (LOG_SYSLOG | (PRI)) % 10, \
35 '>'
36
37static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
38
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070039// Parsing is hard
40
41// called if we see a '<', s is the next character, returns pointer after '>'
42static char *is_prio(char *s) {
43 if (!isdigit(*s++)) {
44 return NULL;
45 }
Mark Salyzyn618d0de2015-07-13 10:19:34 -070046 static const size_t max_prio_len = 4;
47 size_t len = 0;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070048 char c;
Mark Salyzyn618d0de2015-07-13 10:19:34 -070049 while (((c = *s++)) && (++len <= max_prio_len)) {
Mark Salyzynee49c6a2015-06-12 14:59:42 -070050 if (!isdigit(c)) {
51 return (c == '>') ? s : NULL;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070052 }
53 }
54 return NULL;
55}
56
57// called if we see a '[', s is the next character, returns pointer after ']'
58static char *is_timestamp(char *s) {
59 while (*s == ' ') {
60 ++s;
61 }
62 if (!isdigit(*s++)) {
63 return NULL;
64 }
65 bool first_period = true;
66 char c;
67 while ((c = *s++)) {
68 if ((c == '.') && first_period) {
69 first_period = false;
Mark Salyzynee49c6a2015-06-12 14:59:42 -070070 } else if (!isdigit(c)) {
71 return ((c == ']') && !first_period && (*s == ' ')) ? s : NULL;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070072 }
73 }
74 return NULL;
75}
76
77// Like strtok_r with "\r\n" except that we look for log signatures (regex)
Mark Salyzyn618d0de2015-07-13 10:19:34 -070078// \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \)
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070079// and split if we see a second one without a newline.
80
81#define SIGNATURE_MASK 0xF0
82// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
83#define LESS_THAN_SIG SIGNATURE_MASK
84#define OPEN_BRACKET_SIG ((SIGNATURE_MASK << 1) & SIGNATURE_MASK)
85// space is one more than <digit> of 9
Mark Salyzyn3e21de22015-06-08 14:51:30 -070086#define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10))
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070087
88char *log_strtok_r(char *s, char **last) {
89 if (!s) {
90 if (!(s = *last)) {
91 return NULL;
92 }
93 // fixup for log signature split <,
94 // LESS_THAN_SIG + <digit>
95 if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) {
96 *s = (*s & ~SIGNATURE_MASK) + '0';
97 *--s = '<';
98 }
99 // fixup for log signature split [,
100 // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit>
101 if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) {
102 if (*s == OPEN_BRACKET_SPACE) {
103 *s = ' ';
104 } else {
105 *s = (*s & ~SIGNATURE_MASK) + '0';
106 }
107 *--s = '[';
108 }
109 }
110
111 s += strspn(s, "\r\n");
112
113 if (!*s) { // no non-delimiter characters
114 *last = NULL;
115 return NULL;
116 }
117 char *peek, *tok = s;
118
119 for (;;) {
120 char c = *s++;
121 switch (c) {
122 case '\0':
123 *last = NULL;
124 return tok;
125
126 case '\r':
127 case '\n':
128 s[-1] = '\0';
129 *last = s;
130 return tok;
131
132 case '<':
133 peek = is_prio(s);
134 if (!peek) {
135 break;
136 }
137 if (s != (tok + 1)) { // not first?
138 s[-1] = '\0';
139 *s &= ~SIGNATURE_MASK;
140 *s |= LESS_THAN_SIG; // signature for '<'
141 *last = s;
142 return tok;
143 }
144 s = peek;
145 if ((*s == '[') && ((peek = is_timestamp(s + 1)))) {
146 s = peek;
147 }
148 break;
149
150 case '[':
151 peek = is_timestamp(s);
152 if (!peek) {
153 break;
154 }
155 if (s != (tok + 1)) { // not first?
156 s[-1] = '\0';
157 if (*s == ' ') {
158 *s = OPEN_BRACKET_SPACE;
159 } else {
160 *s &= ~SIGNATURE_MASK;
161 *s |= OPEN_BRACKET_SIG; // signature for '['
162 }
163 *last = s;
164 return tok;
165 }
166 s = peek;
167 break;
168 }
169 }
Mark Salyzyn618d0de2015-07-13 10:19:34 -0700170 // NOTREACHED
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700171}
172
Mark Salyzynae4d9282014-10-15 08:49:39 -0700173log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC);
174
Mark Salyzyn77187782015-05-12 15:21:31 -0700175LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) :
176 SocketListener(fdRead, false),
177 logbuf(buf),
178 reader(reader),
179 signature(CLOCK_MONOTONIC),
Mark Salyzyn77187782015-05-12 15:21:31 -0700180 initialized(false),
181 enableLogging(true),
182 auditd(auditd) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700183 static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n";
184 char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4];
185 snprintf(buffer, sizeof(buffer), klogd_message, priority_message,
186 signature.nsec());
187 write(fdWrite, buffer, strlen(buffer));
188}
189
190bool LogKlog::onDataAvailable(SocketClient *cli) {
191 if (!initialized) {
192 prctl(PR_SET_NAME, "logd.klogd");
193 initialized = true;
194 enableLogging = false;
195 }
196
197 char buffer[LOGGER_ENTRY_MAX_PAYLOAD];
198 size_t len = 0;
199
200 for(;;) {
201 ssize_t retval = 0;
202 if ((sizeof(buffer) - 1 - len) > 0) {
203 retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len);
204 }
205 if ((retval == 0) && (len == 0)) {
206 break;
207 }
208 if (retval < 0) {
209 return false;
210 }
211 len += retval;
212 bool full = len == (sizeof(buffer) - 1);
213 char *ep = buffer + len;
214 *ep = '\0';
215 len = 0;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700216 for(char *ptr = NULL, *tok = buffer;
217 ((tok = log_strtok_r(tok, &ptr)));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700218 tok = NULL) {
219 if (((tok + strlen(tok)) == ep) && (retval != 0) && full) {
220 len = strlen(tok);
221 memmove(buffer, tok, len);
222 break;
223 }
224 if (*tok) {
225 log(tok);
226 }
227 }
228 }
229
230 return true;
231}
232
233
234void LogKlog::calculateCorrection(const log_time &monotonic,
235 const char *real_string) {
236 log_time real;
237 if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) {
238 return;
239 }
240 // kernel report UTC, log_time::strptime is localtime from calendar.
241 // Bionic and liblog strptime does not support %z or %Z to pick up
242 // timezone so we are calculating our own correction.
243 time_t now = real.tv_sec;
244 struct tm tm;
245 memset(&tm, 0, sizeof(tm));
246 tm.tm_isdst = -1;
247 localtime_r(&now, &tm);
248 real.tv_sec += tm.tm_gmtoff;
249 correction = real - monotonic;
250}
251
252void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
253 const char *cp;
254 if ((cp = now.strptime(*buf, "[ %s.%q]"))) {
255 static const char suspend[] = "PM: suspend entry ";
256 static const char resume[] = "PM: suspend exit ";
257 static const char suspended[] = "Suspended for ";
258
259 if (isspace(*cp)) {
260 ++cp;
261 }
262 if (!strncmp(cp, suspend, sizeof(suspend) - 1)) {
263 calculateCorrection(now, cp + sizeof(suspend) - 1);
264 } else if (!strncmp(cp, resume, sizeof(resume) - 1)) {
265 calculateCorrection(now, cp + sizeof(resume) - 1);
266 } else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) {
267 log_time real;
268 char *endp;
269 real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10);
270 if (*endp == '.') {
271 real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L;
272 if (reverse) {
273 correction -= real;
274 } else {
275 correction += real;
276 }
277 }
278 }
279
280 convertMonotonicToReal(now);
281 *buf = cp;
282 } else {
283 now = log_time(CLOCK_REALTIME);
284 }
285}
286
287// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
288// compensated start time.
289void LogKlog::synchronize(const char *buf) {
290 const char *cp = strstr(buf, "] PM: suspend e");
291 if (!cp) {
292 return;
293 }
294
295 do {
296 --cp;
297 } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.')));
298
299 log_time now;
300 sniffTime(now, &cp, true);
301
302 char *suspended = strstr(buf, "] Suspended for ");
303 if (!suspended || (suspended > cp)) {
304 return;
305 }
306 cp = suspended;
307
308 do {
309 --cp;
310 } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.')));
311
312 sniffTime(now, &cp, true);
313}
314
315// kernel log prefix, convert to a kernel log priority number
316static int parseKernelPrio(const char **buf) {
317 int pri = LOG_USER | LOG_INFO;
318 const char *cp = *buf;
319 if (*cp == '<') {
320 pri = 0;
321 while(isdigit(*++cp)) {
322 pri = (pri * 10) + *cp - '0';
323 }
324 if (*cp == '>') {
325 ++cp;
326 } else {
327 cp = *buf;
328 pri = LOG_USER | LOG_INFO;
329 }
330 *buf = cp;
331 }
332 return pri;
333}
334
335// Convert kernel log priority number into an Android Logger priority number
336static int convertKernelPrioToAndroidPrio(int pri) {
337 switch(pri & LOG_PRIMASK) {
338 case LOG_EMERG:
339 // FALLTHRU
340 case LOG_ALERT:
341 // FALLTHRU
342 case LOG_CRIT:
343 return ANDROID_LOG_FATAL;
344
345 case LOG_ERR:
346 return ANDROID_LOG_ERROR;
347
348 case LOG_WARNING:
349 return ANDROID_LOG_WARN;
350
351 default:
352 // FALLTHRU
353 case LOG_NOTICE:
354 // FALLTHRU
355 case LOG_INFO:
356 break;
357
358 case LOG_DEBUG:
359 return ANDROID_LOG_DEBUG;
360 }
361
362 return ANDROID_LOG_INFO;
363}
364
365//
366// log a message into the kernel log buffer
367//
368// Filter rules to parse <PRI> <TIME> <tag> and <message> in order for
369// them to appear correct in the logcat output:
370//
371// LOG_KERN (0):
372// <PRI>[<TIME>] <tag> ":" <message>
373// <PRI>[<TIME>] <tag> <tag> ":" <message>
374// <PRI>[<TIME>] <tag> <tag>_work ":" <message>
375// <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message>
376// <PRI>[<TIME>] <tag> '<tag><num>' ":" <message>
377// <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message>
378// (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message>
379// <PRI>[<TIME>] "[INFO]"<tag> : <message>
380// <PRI>[<TIME>] "------------[ cut here ]------------" (?)
381// <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---" (?)
382// LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS
383// LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP:
384// <PRI+TAG>[<TIME>] (see sys/syslog.h)
385// Observe:
386// Minimum tag length = 3 NB: drops things like r5:c00bbadf, but allow PM:
387// Maximum tag words = 2
388// Maximum tag length = 16 NB: we are thinking of how ugly logcat can get.
389// Not a Tag if there is no message content.
390// leading additional spaces means no tag, inherit last tag.
391// Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:"
392// Drop:
393// empty messages
394// messages with ' audit(' in them if auditd is running
395// logd.klogd:
396// return -1 if message logd.klogd: <signature>
397//
398int LogKlog::log(const char *buf) {
399 if (auditd && strstr(buf, " audit(")) {
400 return 0;
401 }
402
403 int pri = parseKernelPrio(&buf);
404
405 log_time now;
406 sniffTime(now, &buf, false);
407
408 // sniff for start marker
409 const char klogd_message[] = "logd.klogd: ";
410 if (!strncmp(buf, klogd_message, sizeof(klogd_message) - 1)) {
411 char *endp;
412 uint64_t sig = strtoll(buf + sizeof(klogd_message) - 1, &endp, 10);
413 if (sig == signature.nsec()) {
414 if (initialized) {
415 enableLogging = true;
416 } else {
417 enableLogging = false;
418 }
419 return -1;
420 }
421 return 0;
422 }
423
424 if (!enableLogging) {
425 return 0;
426 }
427
428 // Parse pid, tid and uid (not possible)
429 const pid_t pid = 0;
430 const pid_t tid = 0;
431 const uid_t uid = 0;
432
433 // Parse (rules at top) to pull out a tag from the incoming kernel message.
434 // Some may view the following as an ugly heuristic, the desire is to
435 // beautify the kernel logs into an Android Logging format; the goal is
436 // admirable but costly.
437 while (isspace(*buf)) {
438 ++buf;
439 }
440 if (!*buf) {
441 return 0;
442 }
443 const char *start = buf;
444 const char *tag = "";
445 const char *etag = tag;
446 if (!isspace(*buf)) {
447 const char *bt, *et, *cp;
448
449 bt = buf;
450 if (!strncmp(buf, "[INFO]", 6)) {
451 // <PRI>[<TIME>] "[INFO]"<tag> ":" message
452 bt = buf + 6;
453 }
454 for(et = bt; *et && (*et != ':') && !isspace(*et); ++et);
455 for(cp = et; isspace(*cp); ++cp);
456 size_t size;
457
458 if (*cp == ':') {
459 // One Word
460 tag = bt;
461 etag = et;
462 buf = cp + 1;
463 } else {
464 size = et - bt;
465 if (strncmp(bt, cp, size)) {
466 // <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
467 if (!strncmp(bt + size - 5, "_host", 5)
Mark Salyzyn618d0de2015-07-13 10:19:34 -0700468 && !strncmp(bt, cp, size - 5)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700469 const char *b = cp;
470 cp += size - 5;
471 if (*cp == '.') {
472 while (!isspace(*++cp) && (*cp != ':'));
473 const char *e;
474 for(e = cp; isspace(*cp); ++cp);
475 if (*cp == ':') {
476 tag = b;
477 etag = e;
478 buf = cp + 1;
479 }
480 }
481 } else {
482 while (!isspace(*++cp) && (*cp != ':'));
483 const char *e;
484 for(e = cp; isspace(*cp); ++cp);
485 // Two words
486 if (*cp == ':') {
487 tag = bt;
488 etag = e;
489 buf = cp + 1;
490 }
491 }
492 } else if (isspace(cp[size])) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700493 cp += size;
494 while (isspace(*++cp));
495 // <PRI>[<TIME>] <tag> <tag> : message
496 if (*cp == ':') {
497 tag = bt;
498 etag = et;
499 buf = cp + 1;
500 }
501 } else if (cp[size] == ':') {
502 // <PRI>[<TIME>] <tag> <tag> : message
503 tag = bt;
504 etag = et;
505 buf = cp + size + 1;
506 } else if ((cp[size] == '.') || isdigit(cp[size])) {
507 // <PRI>[<TIME>] <tag> '<tag>.<num>' : message
508 // <PRI>[<TIME>] <tag> '<tag><num>' : message
509 const char *b = cp;
510 cp += size;
511 while (!isspace(*++cp) && (*cp != ':'));
512 const char *e = cp;
513 while (isspace(*cp)) {
514 ++cp;
515 }
516 if (*cp == ':') {
517 tag = b;
518 etag = e;
519 buf = cp + 1;
520 }
521 } else {
522 while (!isspace(*++cp) && (*cp != ':'));
523 const char *e = cp;
524 while (isspace(*cp)) {
525 ++cp;
526 }
527 // Two words
528 if (*cp == ':') {
529 tag = bt;
530 etag = e;
531 buf = cp + 1;
532 }
533 }
534 }
535 size = etag - tag;
536 if ((size <= 1)
Mark Salyzyn618d0de2015-07-13 10:19:34 -0700537 // register names like x9
538 || ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1])))
539 // register names like x18 but not driver names like en0
540 || ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2])))
541 // blacklist
542 || ((size == 3) && !strncmp(tag, "CPU", 3))
543 || ((size == 7) && !strncmp(tag, "WARNING", 7))
544 || ((size == 5) && !strncmp(tag, "ERROR", 5))
545 || ((size == 4) && !strncmp(tag, "INFO", 4))) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700546 buf = start;
547 etag = tag = "";
548 }
549 }
550 size_t l = etag - tag;
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700551 // skip leading space
Mark Salyzynae4d9282014-10-15 08:49:39 -0700552 while (isspace(*buf)) {
553 ++buf;
554 }
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700555 // truncate trailing space
556 size_t b = strlen(buf);
557 while (b && isspace(buf[b-1])) {
558 --b;
559 }
560 // trick ... allow tag with empty content to be logged. log() drops empty
561 if (!b && l) {
562 buf = " ";
563 b = 1;
564 }
565 size_t n = 1 + l + 1 + b + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700566
567 // Allocate a buffer to hold the interpreted log message
568 int rc = n;
569 char *newstr = reinterpret_cast<char *>(malloc(n));
570 if (!newstr) {
571 rc = -ENOMEM;
572 return rc;
573 }
574 char *np = newstr;
575
576 // Convert priority into single-byte Android logger priority
577 *np = convertKernelPrioToAndroidPrio(pri);
578 ++np;
579
580 // Copy parsed tag following priority
581 strncpy(np, tag, l);
582 np += l;
583 *np = '\0';
584 ++np;
585
586 // Copy main message to the remainder
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700587 strncpy(np, buf, b);
588 np[b] = '\0';
Mark Salyzynae4d9282014-10-15 08:49:39 -0700589
590 // Log message
591 rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr,
592 (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX);
593 free(newstr);
594
595 // notify readers
596 if (!rc) {
597 reader->notifyNewLog();
598 }
599
600 return rc;
601}