blob: ac2b128956c94325792a6c390f5c71fe6299ade2 [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>
Mark Salyzyn2ad0bd02016-02-23 08:55:43 -080023#include <string.h>
Mark Salyzynae4d9282014-10-15 08:49:39 -070024#include <sys/prctl.h>
25#include <sys/uio.h>
26#include <syslog.h>
27
28#include <log/logger.h>
29
Mark Salyzyn2ad0bd02016-02-23 08:55:43 -080030#include "LogBuffer.h"
Mark Salyzynae4d9282014-10-15 08:49:39 -070031#include "LogKlog.h"
Mark Salyzyn2ad0bd02016-02-23 08:55:43 -080032#include "LogReader.h"
Mark Salyzynae4d9282014-10-15 08:49:39 -070033
34#define KMSG_PRIORITY(PRI) \
35 '<', \
36 '0' + (LOG_SYSLOG | (PRI)) / 10, \
37 '0' + (LOG_SYSLOG | (PRI)) % 10, \
38 '>'
39
40static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
41
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070042// Parsing is hard
43
44// called if we see a '<', s is the next character, returns pointer after '>'
Mark Salyzynea1a2412015-09-02 07:39:53 -070045static char *is_prio(char *s, size_t len) {
46 if (!len || !isdigit(*s++)) {
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070047 return NULL;
48 }
Mark Salyzynea1a2412015-09-02 07:39:53 -070049 --len;
50 static const size_t max_prio_len = (len < 4) ? len : 4;
51 size_t priolen = 0;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070052 char c;
Mark Salyzynea1a2412015-09-02 07:39:53 -070053 while (((c = *s++)) && (++priolen <= max_prio_len)) {
Mark Salyzynee49c6a2015-06-12 14:59:42 -070054 if (!isdigit(c)) {
Mark Salyzyn46d159d2015-08-26 09:30:00 -070055 return ((c == '>') && (*s == '[')) ? s : NULL;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070056 }
57 }
58 return NULL;
59}
60
61// called if we see a '[', s is the next character, returns pointer after ']'
Mark Salyzynea1a2412015-09-02 07:39:53 -070062static char *is_timestamp(char *s, size_t len) {
63 while (len && (*s == ' ')) {
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070064 ++s;
Mark Salyzynea1a2412015-09-02 07:39:53 -070065 --len;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070066 }
Mark Salyzynea1a2412015-09-02 07:39:53 -070067 if (!len || !isdigit(*s++)) {
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070068 return NULL;
69 }
Mark Salyzynea1a2412015-09-02 07:39:53 -070070 --len;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070071 bool first_period = true;
72 char c;
Mark Salyzynea1a2412015-09-02 07:39:53 -070073 while (len && ((c = *s++))) {
74 --len;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070075 if ((c == '.') && first_period) {
76 first_period = false;
Mark Salyzynee49c6a2015-06-12 14:59:42 -070077 } else if (!isdigit(c)) {
78 return ((c == ']') && !first_period && (*s == ' ')) ? s : NULL;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070079 }
80 }
81 return NULL;
82}
83
84// Like strtok_r with "\r\n" except that we look for log signatures (regex)
Mark Salyzyn618d0de2015-07-13 10:19:34 -070085// \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \)
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070086// and split if we see a second one without a newline.
Mark Salyzyn151beac2015-09-04 11:37:42 -070087// We allow nuls in content, monitoring the overall length and sub-length of
88// the discovered tokens.
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070089
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
Mark Salyzyn3e21de22015-06-08 14:51:30 -070095#define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10))
Mark Salyzyn2c3b3002015-05-22 15:23:44 -070096
Mark Salyzynea1a2412015-09-02 07:39:53 -070097char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) {
98 *sublen = 0;
99 if (!*len) {
100 return NULL;
101 }
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700102 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 = '<';
Mark Salyzynea1a2412015-09-02 07:39:53 -0700111 ++*len;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700112 }
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 = '[';
Mark Salyzynea1a2412015-09-02 07:39:53 -0700122 ++*len;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700123 }
124 }
125
Mark Salyzynea1a2412015-09-02 07:39:53 -0700126 while (*len && ((*s == '\r') || (*s == '\n'))) {
127 ++s;
128 --*len;
129 }
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700130
Mark Salyzynea1a2412015-09-02 07:39:53 -0700131 if (!*len) {
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700132 *last = NULL;
133 return NULL;
134 }
135 char *peek, *tok = s;
136
137 for (;;) {
Mark Salyzynea1a2412015-09-02 07:39:53 -0700138 if (*len == 0) {
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700139 *last = NULL;
140 return tok;
Mark Salyzynea1a2412015-09-02 07:39:53 -0700141 }
142 char c = *s++;
143 --*len;
144 size_t adjust;
145 switch (c) {
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700146 case '\r':
147 case '\n':
148 s[-1] = '\0';
149 *last = s;
150 return tok;
151
152 case '<':
Mark Salyzynea1a2412015-09-02 07:39:53 -0700153 peek = is_prio(s, *len);
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700154 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 }
Mark Salyzynea1a2412015-09-02 07:39:53 -0700164 adjust = peek - s;
165 if (adjust > *len) {
166 adjust = *len;
167 }
168 *sublen += adjust;
169 *len -= adjust;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700170 s = peek;
Mark Salyzynea1a2412015-09-02 07:39:53 -0700171 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;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700178 s = peek;
179 }
180 break;
181
182 case '[':
Mark Salyzynea1a2412015-09-02 07:39:53 -0700183 peek = is_timestamp(s, *len);
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700184 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 }
Mark Salyzynea1a2412015-09-02 07:39:53 -0700198 adjust = peek - s;
199 if (adjust > *len) {
200 adjust = *len;
201 }
202 *sublen += adjust;
203 *len -= adjust;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700204 s = peek;
205 break;
206 }
Mark Salyzynea1a2412015-09-02 07:39:53 -0700207 ++*sublen;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700208 }
Mark Salyzyn618d0de2015-07-13 10:19:34 -0700209 // NOTREACHED
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700210}
211
Mark Salyzyn10b82b62015-12-28 15:33:01 -0800212log_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));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700216
Mark Salyzyn77187782015-05-12 15:21:31 -0700217LogKlog::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),
Mark Salyzyn77187782015-05-12 15:21:31 -0700222 initialized(false),
223 enableLogging(true),
224 auditd(auditd) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700225 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
232bool 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';
Mark Salyzynea1a2412015-09-02 07:39:53 -0700257 size_t sublen;
Mark Salyzyn2c3b3002015-05-22 15:23:44 -0700258 for(char *ptr = NULL, *tok = buffer;
Mark Salyzynea1a2412015-09-02 07:39:53 -0700259 ((tok = log_strntok_r(tok, &len, &ptr, &sublen)));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700260 tok = NULL) {
Mark Salyzynea1a2412015-09-02 07:39:53 -0700261 if (((tok + sublen) >= ep) && (retval != 0) && full) {
262 memmove(buffer, tok, sublen);
263 len = sublen;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700264 break;
265 }
266 if (*tok) {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700267 log(tok, sublen);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700268 }
269 }
270 }
271
272 return true;
273}
274
275
276void LogKlog::calculateCorrection(const log_time &monotonic,
Mark Salyzyn151beac2015-09-04 11:37:42 -0700277 const char *real_string,
278 size_t len) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700279 log_time real;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700280 const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC");
Mark Salyzyn10b82b62015-12-28 15:33:01 -0800281 if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700282 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);
Mark Salyzynff8b8e82015-12-30 13:46:07 -0800292 if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > (long)real.tv_sec)) {
Mark Salyzyn10b82b62015-12-28 15:33:01 -0800293 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 }
Mark Salyzynae4d9282014-10-15 08:49:39 -0700302}
303
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700304static const char suspendStr[] = "PM: suspend entry ";
305static const char resumeStr[] = "PM: suspend exit ";
306static const char suspendedStr[] = "Suspended for ";
307
Mark Salyzyn151beac2015-09-04 11:37:42 -0700308static 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);
Mark Salyzynddda2122015-10-02 09:22:52 -0700323 } while (fast<memcmp>(s, needle, needleLen));
Mark Salyzyn151beac2015-09-04 11:37:42 -0700324 s--;
325 }
326 return s;
327}
328
329void 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 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700336 if (cp) {
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700337 static const char healthd[] = "healthd";
338 static const char battery[] = ": battery ";
Mark Salyzynae4d9282014-10-15 08:49:39 -0700339
Mark Salyzyn10b82b62015-12-28 15:33:01 -0800340 len -= cp - *buf;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700341 if (len && isspace(*cp)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700342 ++cp;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700343 --len;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700344 }
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700345 *buf = cp;
346
Mark Salyzynb6bee332015-09-08 08:56:32 -0700347 if (isMonotonic()) {
348 return;
349 }
350
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700351 const char *b;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700352 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)) {
Mark Salyzyn10b82b62015-12-28 15:33:01 -0800364 // 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);
Mark Salyzyn151beac2015-09-04 11:37:42 -0700369 } else if (((b = strnstr(cp, len, suspendedStr)))
370 && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
371 len -= b - cp;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700372 log_time real;
373 char *endp;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700374 real.tv_sec = strtol(b, &endp, 10);
375 if ((*endp == '.') && ((size_t)(endp - b) < len)) {
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700376 unsigned long multiplier = NS_PER_SEC;
377 real.tv_nsec = 0;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700378 len -= endp - b;
379 while (--len && isdigit(*++endp) && (multiplier /= 10)) {
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700380 real.tv_nsec += (*endp - '0') * multiplier;
381 }
Mark Salyzynae4d9282014-10-15 08:49:39 -0700382 if (reverse) {
Mark Salyzyn10b82b62015-12-28 15:33:01 -0800383 if (real > correction) {
384 correction = log_time::EPOCH;
385 } else {
386 correction -= real;
387 }
Mark Salyzynae4d9282014-10-15 08:49:39 -0700388 } else {
389 correction += real;
390 }
391 }
392 }
393
394 convertMonotonicToReal(now);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700395 } else {
Mark Salyzynb6bee332015-09-08 08:56:32 -0700396 if (isMonotonic()) {
397 now = log_time(CLOCK_MONOTONIC);
398 } else {
399 now = log_time(CLOCK_REALTIME);
400 }
Mark Salyzynae4d9282014-10-15 08:49:39 -0700401 }
402}
403
Mark Salyzyn151beac2015-09-04 11:37:42 -0700404pid_t LogKlog::sniffPid(const char *cp, size_t len) {
405 while (len) {
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700406 // 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;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700416 --len;
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700417 }
418 return 0;
419}
420
Mark Salyzynae4d9282014-10-15 08:49:39 -0700421// kernel log prefix, convert to a kernel log priority number
Mark Salyzyn151beac2015-09-04 11:37:42 -0700422static int parseKernelPrio(const char **buf, size_t len) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700423 int pri = LOG_USER | LOG_INFO;
424 const char *cp = *buf;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700425 if (len && (*cp == '<')) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700426 pri = 0;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700427 while(--len && isdigit(*++cp)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700428 pri = (pri * 10) + *cp - '0';
429 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700430 if (len && (*cp == '>')) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700431 ++cp;
432 } else {
433 cp = *buf;
434 pri = LOG_USER | LOG_INFO;
435 }
436 *buf = cp;
437 }
438 return pri;
439}
440
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700441// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
442// compensated start time.
Mark Salyzyn151beac2015-09-04 11:37:42 -0700443void LogKlog::synchronize(const char *buf, size_t len) {
444 const char *cp = strnstr(buf, len, suspendStr);
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700445 if (!cp) {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700446 cp = strnstr(buf, len, resumeStr);
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700447 if (!cp) {
448 return;
449 }
450 } else {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700451 const char *rp = strnstr(buf, len, resumeStr);
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700452 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 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700463 parseKernelPrio(&cp, len - (cp - buf));
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700464
465 log_time now;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700466 sniffTime(now, &cp, len - (cp - buf), true);
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700467
Mark Salyzyn151beac2015-09-04 11:37:42 -0700468 const char *suspended = strnstr(buf, len, suspendedStr);
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700469 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 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700480 parseKernelPrio(&cp, len - (cp - buf));
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700481
Mark Salyzyn151beac2015-09-04 11:37:42 -0700482 sniffTime(now, &cp, len - (cp - buf), true);
Mark Salyzyn2d159bf2015-09-01 13:09:23 -0700483}
484
Mark Salyzynae4d9282014-10-15 08:49:39 -0700485// Convert kernel log priority number into an Android Logger priority number
486static 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
Mark Salyzyn47dba712015-08-26 09:30:00 -0700515static 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
Mark Salyzynae4d9282014-10-15 08:49:39 -0700525//
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//
Mark Salyzyn151beac2015-09-04 11:37:42 -0700558int LogKlog::log(const char *buf, size_t len) {
559 if (auditd && strnstr(buf, len, " audit(")) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700560 return 0;
561 }
562
Mark Salyzyn151beac2015-09-04 11:37:42 -0700563 const char *p = buf;
564 int pri = parseKernelPrio(&p, len);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700565
566 log_time now;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700567 sniffTime(now, &p, len - (p - buf), false);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700568
569 // sniff for start marker
570 const char klogd_message[] = "logd.klogd: ";
Mark Salyzyn151beac2015-09-04 11:37:42 -0700571 const char *start = strnstr(p, len - (p - buf), klogd_message);
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700572 if (start) {
573 uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700574 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
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700589 // Parse pid, tid and uid
Mark Salyzyn151beac2015-09-04 11:37:42 -0700590 const pid_t pid = sniffPid(p, len - (p - buf));
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700591 const pid_t tid = pid;
592 const uid_t uid = pid ? logbuf->pidToUid(pid) : 0;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700593
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.
Mark Salyzyneb298082015-11-10 15:56:41 -0800598 while ((p < &buf[len]) && (isspace(*p) || !*p)) {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700599 ++p;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700600 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700601 if (p >= &buf[len]) { // timestamp, no content
Mark Salyzynae4d9282014-10-15 08:49:39 -0700602 return 0;
603 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700604 start = p;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700605 const char *tag = "";
606 const char *etag = tag;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700607 size_t taglen = len - (p - buf);
608 if (!isspace(*p) && *p) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700609 const char *bt, *et, *cp;
610
Mark Salyzyn151beac2015-09-04 11:37:42 -0700611 bt = p;
Mark Salyzyneb298082015-11-10 15:56:41 -0800612 if ((taglen >= 6) && !fast<strncmp>(p, "[INFO]", 6)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700613 // <PRI>[<TIME>] "[INFO]"<tag> ":" message
Mark Salyzyn151beac2015-09-04 11:37:42 -0700614 bt = p + 6;
615 taglen -= 6;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700616 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700617 for(et = bt; taglen && *et && (*et != ':') && !isspace(*et); ++et, --taglen) {
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700618 // skip ':' within [ ... ]
619 if (*et == '[') {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700620 while (taglen && *et && *et != ']') {
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700621 ++et;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700622 --taglen;
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700623 }
624 }
625 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700626 for(cp = et; taglen && isspace(*cp); ++cp, --taglen);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700627 size_t size;
628
629 if (*cp == ':') {
630 // One Word
631 tag = bt;
632 etag = et;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700633 p = cp + 1;
634 } else if (taglen) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700635 size = et - bt;
Mark Salyzyneb298082015-11-10 15:56:41 -0800636 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)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700639 // <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
Mark Salyzynddda2122015-10-02 09:22:52 -0700640 if (!fast<strncmp>(bt + size - 5, "_host", 5)
641 && !fast<strncmp>(bt + 1, cp + 1, size - 6)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700642 const char *b = cp;
643 cp += size - 5;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700644 taglen -= size - 5;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700645 if (*cp == '.') {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700646 while (--taglen && !isspace(*++cp) && (*cp != ':'));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700647 const char *e;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700648 for(e = cp; taglen && isspace(*cp); ++cp, --taglen);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700649 if (*cp == ':') {
650 tag = b;
651 etag = e;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700652 p = cp + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700653 }
654 }
655 } else {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700656 while (--taglen && !isspace(*++cp) && (*cp != ':'));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700657 const char *e;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700658 for(e = cp; taglen && isspace(*cp); ++cp, --taglen);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700659 // Two words
660 if (*cp == ':') {
661 tag = bt;
662 etag = e;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700663 p = cp + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700664 }
665 }
666 } else if (isspace(cp[size])) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700667 cp += size;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700668 taglen -= size;
669 while (--taglen && isspace(*++cp));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700670 // <PRI>[<TIME>] <tag> <tag> : message
671 if (*cp == ':') {
672 tag = bt;
673 etag = et;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700674 p = cp + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700675 }
676 } else if (cp[size] == ':') {
677 // <PRI>[<TIME>] <tag> <tag> : message
678 tag = bt;
679 etag = et;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700680 p = cp + size + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700681 } 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;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700686 taglen -= size;
687 while (--taglen && !isspace(*++cp) && (*cp != ':'));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700688 const char *e = cp;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700689 while (taglen && isspace(*cp)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700690 ++cp;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700691 --taglen;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700692 }
693 if (*cp == ':') {
694 tag = b;
695 etag = e;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700696 p = cp + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700697 }
698 } else {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700699 while (--taglen && !isspace(*++cp) && (*cp != ':'));
Mark Salyzynae4d9282014-10-15 08:49:39 -0700700 const char *e = cp;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700701 while (taglen && isspace(*cp)) {
Mark Salyzynae4d9282014-10-15 08:49:39 -0700702 ++cp;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700703 --taglen;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700704 }
705 // Two words
706 if (*cp == ':') {
707 tag = bt;
708 etag = e;
Mark Salyzyn151beac2015-09-04 11:37:42 -0700709 p = cp + 1;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700710 }
711 }
Mark Salyzyneb298082015-11-10 15:56:41 -0800712 } /* else no tag */
Mark Salyzynae4d9282014-10-15 08:49:39 -0700713 size = etag - tag;
714 if ((size <= 1)
Mark Salyzyn618d0de2015-07-13 10:19:34 -0700715 // 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
Mark Salyzynddda2122015-10-02 09:22:52 -0700720 || ((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))) {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700724 p = start;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700725 etag = tag = "";
726 }
727 }
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700728 // Suppress additional stutter in tag:
729 // eg: [143:healthd]healthd -> [143:healthd]
Mark Salyzyn151beac2015-09-04 11:37:42 -0700730 taglen = etag - tag;
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700731 // Mediatek-special printk induced stutter
Mark Salyzyn47dba712015-08-26 09:30:00 -0700732 const char *mp = strnrchr(tag, ']', taglen);
733 if (mp && (++mp < etag)) {
734 size_t s = etag - mp;
Mark Salyzynddda2122015-10-02 09:22:52 -0700735 if (((s + s) < taglen) && !fast<memcmp>(mp, mp - 1 - s, s)) {
Mark Salyzyn47dba712015-08-26 09:30:00 -0700736 taglen = mp - tag;
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700737 }
738 }
Mark Salyzyneb298082015-11-10 15:56:41 -0800739 // Deal with sloppy and simplistic harmless p = cp + 1 etc above.
740 if (len < (size_t)(p - buf)) {
741 p = &buf[len];
742 }
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700743 // skip leading space
Mark Salyzyneb298082015-11-10 15:56:41 -0800744 while ((p < &buf[len]) && (isspace(*p) || !*p)) {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700745 ++p;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700746 }
Mark Salyzyn151beac2015-09-04 11:37:42 -0700747 // truncate trailing space or nuls
748 size_t b = len - (p - buf);
749 while (b && (isspace(p[b-1]) || !p[b-1])) {
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700750 --b;
751 }
752 // trick ... allow tag with empty content to be logged. log() drops empty
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700753 if (!b && taglen) {
Mark Salyzyn151beac2015-09-04 11:37:42 -0700754 p = " ";
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700755 b = 1;
756 }
Mark Salyzyneb298082015-11-10 15:56:41 -0800757 // paranoid sanity check, can not happen ...
Mark Salyzynddda2122015-10-02 09:22:52 -0700758 if (b > LOGGER_ENTRY_MAX_PAYLOAD) {
759 b = LOGGER_ENTRY_MAX_PAYLOAD;
760 }
Mark Salyzyneb298082015-11-10 15:56:41 -0800761 if (taglen > LOGGER_ENTRY_MAX_PAYLOAD) {
762 taglen = LOGGER_ENTRY_MAX_PAYLOAD;
763 }
764 // calculate buffer copy requirements
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700765 size_t n = 1 + taglen + 1 + b + 1;
Mark Salyzyneb298082015-11-10 15:56:41 -0800766 // paranoid sanity check, first two just can not happen ...
767 if ((taglen > n) || (b > n) || (n > USHRT_MAX)) {
768 return -EINVAL;
Mark Salyzyn47dba712015-08-26 09:30:00 -0700769 }
Mark Salyzynae4d9282014-10-15 08:49:39 -0700770
Mark Salyzyneb298082015-11-10 15:56:41 -0800771 // 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.
Mark Salyzynddda2122015-10-02 09:22:52 -0700777 char newstr[n];
Mark Salyzyn47dba712015-08-26 09:30:00 -0700778 char *np = newstr;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700779
780 // Convert priority into single-byte Android logger priority
781 *np = convertKernelPrioToAndroidPrio(pri);
782 ++np;
783
784 // Copy parsed tag following priority
Mark Salyzyn151beac2015-09-04 11:37:42 -0700785 memcpy(np, tag, taglen);
Mark Salyzyn46d159d2015-08-26 09:30:00 -0700786 np += taglen;
Mark Salyzynae4d9282014-10-15 08:49:39 -0700787 *np = '\0';
788 ++np;
789
790 // Copy main message to the remainder
Mark Salyzyn151beac2015-09-04 11:37:42 -0700791 memcpy(np, p, b);
Mark Salyzynee49c6a2015-06-12 14:59:42 -0700792 np[b] = '\0';
Mark Salyzynae4d9282014-10-15 08:49:39 -0700793
Mark Salyzynb06247d2015-12-04 09:32:27 -0800794 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
Mark Salyzynae4d9282014-10-15 08:49:39 -0700819 // Log message
Mark Salyzyneb298082015-11-10 15:56:41 -0800820 int rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr,
821 (unsigned short) n);
Mark Salyzynae4d9282014-10-15 08:49:39 -0700822
823 // notify readers
824 if (!rc) {
825 reader->notifyNewLog();
826 }
827
828 return rc;
829}