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 <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
39// 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    }
46    char c;
47    while ((c = *s++)) {
48        if (!isdigit(c)) {
49            return (c == '>') ? s : NULL;
50        }
51    }
52    return NULL;
53}
54
55// called if we see a '[', s is the next character, returns pointer after ']'
56static char *is_timestamp(char *s) {
57    while (*s == ' ') {
58        ++s;
59    }
60    if (!isdigit(*s++)) {
61        return NULL;
62    }
63    bool first_period = true;
64    char c;
65    while ((c = *s++)) {
66        if ((c == '.') && first_period) {
67            first_period = false;
68        } else if (!isdigit(c)) {
69            return ((c == ']') && !first_period && (*s == ' ')) ? s : NULL;
70        }
71    }
72    return NULL;
73}
74
75// Like strtok_r with "\r\n" except that we look for log signatures (regex)
76// \(\(<[0-9]+>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \)
77// and split if we see a second one without a newline.
78
79#define SIGNATURE_MASK     0xF0
80// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
81#define LESS_THAN_SIG      SIGNATURE_MASK
82#define OPEN_BRACKET_SIG   ((SIGNATURE_MASK << 1) & SIGNATURE_MASK)
83// space is one more than <digit> of 9
84#define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10))
85
86char *log_strtok_r(char *s, char **last) {
87    if (!s) {
88        if (!(s = *last)) {
89            return NULL;
90        }
91        // fixup for log signature split <,
92        // LESS_THAN_SIG + <digit>
93        if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) {
94            *s = (*s & ~SIGNATURE_MASK) + '0';
95            *--s = '<';
96        }
97        // fixup for log signature split [,
98        // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit>
99        if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) {
100            if (*s == OPEN_BRACKET_SPACE) {
101                *s = ' ';
102            } else {
103                *s = (*s & ~SIGNATURE_MASK) + '0';
104            }
105            *--s = '[';
106        }
107    }
108
109    s += strspn(s, "\r\n");
110
111    if (!*s) { // no non-delimiter characters
112        *last = NULL;
113        return NULL;
114    }
115    char *peek, *tok = s;
116
117    for (;;) {
118        char c = *s++;
119        switch (c) {
120        case '\0':
121            *last = NULL;
122            return tok;
123
124        case '\r':
125        case '\n':
126            s[-1] = '\0';
127            *last = s;
128            return tok;
129
130        case '<':
131            peek = is_prio(s);
132            if (!peek) {
133                break;
134            }
135            if (s != (tok + 1)) { // not first?
136                s[-1] = '\0';
137                *s &= ~SIGNATURE_MASK;
138                *s |= LESS_THAN_SIG; // signature for '<'
139                *last = s;
140                return tok;
141            }
142            s = peek;
143            if ((*s == '[') && ((peek = is_timestamp(s + 1)))) {
144                s = peek;
145            }
146            break;
147
148        case '[':
149            peek = is_timestamp(s);
150            if (!peek) {
151                break;
152            }
153            if (s != (tok + 1)) { // not first?
154                s[-1] = '\0';
155                if (*s == ' ') {
156                    *s = OPEN_BRACKET_SPACE;
157                } else {
158                    *s &= ~SIGNATURE_MASK;
159                    *s |= OPEN_BRACKET_SIG; // signature for '['
160                }
161                *last = s;
162                return tok;
163            }
164            s = peek;
165            break;
166        }
167    }
168    /* NOTREACHED */
169}
170
171log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC);
172
173LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) :
174        SocketListener(fdRead, false),
175        logbuf(buf),
176        reader(reader),
177        signature(CLOCK_MONOTONIC),
178        fdWrite(fdWrite),
179        fdRead(fdRead),
180        initialized(false),
181        enableLogging(true),
182        auditd(auditd) {
183    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;
216        for(char *ptr = NULL, *tok = buffer;
217                ((tok = log_strtok_r(tok, &ptr)));
218                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)
468                 && !strncmp(bt, cp, size - 5)) {
469                    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])) {
493                const char *b = cp;
494                cp += size;
495                while (isspace(*++cp));
496                // <PRI>[<TIME>] <tag> <tag> : message
497                if (*cp == ':') {
498                    tag = bt;
499                    etag = et;
500                    buf = cp + 1;
501                }
502            } else if (cp[size] == ':') {
503                // <PRI>[<TIME>] <tag> <tag> : message
504                tag = bt;
505                etag = et;
506                buf = cp + size + 1;
507            } else if ((cp[size] == '.') || isdigit(cp[size])) {
508                // <PRI>[<TIME>] <tag> '<tag>.<num>' : message
509                // <PRI>[<TIME>] <tag> '<tag><num>' : message
510                const char *b = cp;
511                cp += size;
512                while (!isspace(*++cp) && (*cp != ':'));
513                const char *e = cp;
514                while (isspace(*cp)) {
515                    ++cp;
516                }
517                if (*cp == ':') {
518                    tag = b;
519                    etag = e;
520                    buf = cp + 1;
521                }
522            } else {
523                while (!isspace(*++cp) && (*cp != ':'));
524                const char *e = cp;
525                while (isspace(*cp)) {
526                    ++cp;
527                }
528                // Two words
529                if (*cp == ':') {
530                    tag = bt;
531                    etag = e;
532                    buf = cp + 1;
533                }
534            }
535        }
536        size = etag - tag;
537        if ((size <= 1)
538         || ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1])))
539         || ((size == 3) && !strncmp(tag, "CPU", 3))
540         || ((size == 7) && !strncmp(tag, "WARNING", 7))
541         || ((size == 5) && !strncmp(tag, "ERROR", 5))
542         || ((size == 4) && !strncmp(tag, "INFO", 4))) {
543            buf = start;
544            etag = tag = "";
545        }
546    }
547    size_t l = etag - tag;
548    // skip leading space
549    while (isspace(*buf)) {
550        ++buf;
551    }
552    // truncate trailing space
553    size_t b = strlen(buf);
554    while (b && isspace(buf[b-1])) {
555        --b;
556    }
557    // trick ... allow tag with empty content to be logged. log() drops empty
558    if (!b && l) {
559        buf = " ";
560        b = 1;
561    }
562    size_t n = 1 + l + 1 + b + 1;
563
564    // Allocate a buffer to hold the interpreted log message
565    int rc = n;
566    char *newstr = reinterpret_cast<char *>(malloc(n));
567    if (!newstr) {
568        rc = -ENOMEM;
569        return rc;
570    }
571    char *np = newstr;
572
573    // Convert priority into single-byte Android logger priority
574    *np = convertKernelPrioToAndroidPrio(pri);
575    ++np;
576
577    // Copy parsed tag following priority
578    strncpy(np, tag, l);
579    np += l;
580    *np = '\0';
581    ++np;
582
583    // Copy main message to the remainder
584    strncpy(np, buf, b);
585    np[b] = '\0';
586
587    // Log message
588    rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr,
589                     (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX);
590    free(newstr);
591
592    // notify readers
593    if (!rc) {
594        reader->notifyNewLog();
595    }
596
597    return rc;
598}
599