Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 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> |
Mark Salyzyn | 317bfb9 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 23 | #include <string.h> |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 24 | #include <sys/prctl.h> |
| 25 | #include <sys/uio.h> |
| 26 | #include <syslog.h> |
| 27 | |
Mark Salyzyn | aeaaf81 | 2016-09-30 13:30:33 -0700 | [diff] [blame] | 28 | #include <private/android_logger.h> |
Mark Salyzyn | 83b2478 | 2016-08-11 16:07:10 -0700 | [diff] [blame] | 29 | #include <private/android_filesystem_config.h> |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 30 | |
Mark Salyzyn | 317bfb9 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 31 | #include "LogBuffer.h" |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 32 | #include "LogKlog.h" |
Mark Salyzyn | 317bfb9 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 33 | #include "LogReader.h" |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 34 | |
| 35 | #define KMSG_PRIORITY(PRI) \ |
| 36 | '<', \ |
| 37 | '0' + (LOG_SYSLOG | (PRI)) / 10, \ |
| 38 | '0' + (LOG_SYSLOG | (PRI)) % 10, \ |
| 39 | '>' |
| 40 | |
| 41 | static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' }; |
| 42 | |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 43 | // Parsing is hard |
| 44 | |
| 45 | // called if we see a '<', s is the next character, returns pointer after '>' |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 46 | static char *is_prio(char *s, size_t len) { |
| 47 | if (!len || !isdigit(*s++)) { |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 48 | return NULL; |
| 49 | } |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 50 | --len; |
| 51 | static const size_t max_prio_len = (len < 4) ? len : 4; |
| 52 | size_t priolen = 0; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 53 | char c; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 54 | while (((c = *s++)) && (++priolen <= max_prio_len)) { |
Mark Salyzyn | ee49c6a | 2015-06-12 14:59:42 -0700 | [diff] [blame] | 55 | if (!isdigit(c)) { |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 56 | return ((c == '>') && (*s == '[')) ? s : NULL; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 57 | } |
| 58 | } |
| 59 | return NULL; |
| 60 | } |
| 61 | |
| 62 | // called if we see a '[', s is the next character, returns pointer after ']' |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 63 | static char *is_timestamp(char *s, size_t len) { |
| 64 | while (len && (*s == ' ')) { |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 65 | ++s; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 66 | --len; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 67 | } |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 68 | if (!len || !isdigit(*s++)) { |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 69 | return NULL; |
| 70 | } |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 71 | --len; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 72 | bool first_period = true; |
| 73 | char c; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 74 | while (len && ((c = *s++))) { |
| 75 | --len; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 76 | if ((c == '.') && first_period) { |
| 77 | first_period = false; |
Mark Salyzyn | ee49c6a | 2015-06-12 14:59:42 -0700 | [diff] [blame] | 78 | } else if (!isdigit(c)) { |
| 79 | return ((c == ']') && !first_period && (*s == ' ')) ? s : NULL; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 80 | } |
| 81 | } |
| 82 | return NULL; |
| 83 | } |
| 84 | |
| 85 | // Like strtok_r with "\r\n" except that we look for log signatures (regex) |
Mark Salyzyn | 618d0de | 2015-07-13 10:19:34 -0700 | [diff] [blame] | 86 | // \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \) |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 87 | // and split if we see a second one without a newline. |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 88 | // We allow nuls in content, monitoring the overall length and sub-length of |
| 89 | // the discovered tokens. |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 90 | |
| 91 | #define SIGNATURE_MASK 0xF0 |
| 92 | // <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature |
| 93 | #define LESS_THAN_SIG SIGNATURE_MASK |
| 94 | #define OPEN_BRACKET_SIG ((SIGNATURE_MASK << 1) & SIGNATURE_MASK) |
| 95 | // space is one more than <digit> of 9 |
Mark Salyzyn | 3e21de2 | 2015-06-08 14:51:30 -0700 | [diff] [blame] | 96 | #define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10)) |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 97 | |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 98 | char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) { |
| 99 | *sublen = 0; |
| 100 | if (!*len) { |
| 101 | return NULL; |
| 102 | } |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 103 | if (!s) { |
| 104 | if (!(s = *last)) { |
| 105 | return NULL; |
| 106 | } |
| 107 | // fixup for log signature split <, |
| 108 | // LESS_THAN_SIG + <digit> |
| 109 | if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) { |
| 110 | *s = (*s & ~SIGNATURE_MASK) + '0'; |
| 111 | *--s = '<'; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 112 | ++*len; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 113 | } |
| 114 | // fixup for log signature split [, |
| 115 | // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit> |
| 116 | if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) { |
| 117 | if (*s == OPEN_BRACKET_SPACE) { |
| 118 | *s = ' '; |
| 119 | } else { |
| 120 | *s = (*s & ~SIGNATURE_MASK) + '0'; |
| 121 | } |
| 122 | *--s = '['; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 123 | ++*len; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 124 | } |
| 125 | } |
| 126 | |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 127 | while (*len && ((*s == '\r') || (*s == '\n'))) { |
| 128 | ++s; |
| 129 | --*len; |
| 130 | } |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 131 | |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 132 | if (!*len) { |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 133 | *last = NULL; |
| 134 | return NULL; |
| 135 | } |
| 136 | char *peek, *tok = s; |
| 137 | |
| 138 | for (;;) { |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 139 | if (*len == 0) { |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 140 | *last = NULL; |
| 141 | return tok; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 142 | } |
| 143 | char c = *s++; |
| 144 | --*len; |
| 145 | size_t adjust; |
| 146 | switch (c) { |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 147 | case '\r': |
| 148 | case '\n': |
| 149 | s[-1] = '\0'; |
| 150 | *last = s; |
| 151 | return tok; |
| 152 | |
| 153 | case '<': |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 154 | peek = is_prio(s, *len); |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 155 | if (!peek) { |
| 156 | break; |
| 157 | } |
| 158 | if (s != (tok + 1)) { // not first? |
| 159 | s[-1] = '\0'; |
| 160 | *s &= ~SIGNATURE_MASK; |
| 161 | *s |= LESS_THAN_SIG; // signature for '<' |
| 162 | *last = s; |
| 163 | return tok; |
| 164 | } |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 165 | adjust = peek - s; |
| 166 | if (adjust > *len) { |
| 167 | adjust = *len; |
| 168 | } |
| 169 | *sublen += adjust; |
| 170 | *len -= adjust; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 171 | s = peek; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 172 | if ((*s == '[') && ((peek = is_timestamp(s + 1, *len - 1)))) { |
| 173 | adjust = peek - s; |
| 174 | if (adjust > *len) { |
| 175 | adjust = *len; |
| 176 | } |
| 177 | *sublen += adjust; |
| 178 | *len -= adjust; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 179 | s = peek; |
| 180 | } |
| 181 | break; |
| 182 | |
| 183 | case '[': |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 184 | peek = is_timestamp(s, *len); |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 185 | if (!peek) { |
| 186 | break; |
| 187 | } |
| 188 | if (s != (tok + 1)) { // not first? |
| 189 | s[-1] = '\0'; |
| 190 | if (*s == ' ') { |
| 191 | *s = OPEN_BRACKET_SPACE; |
| 192 | } else { |
| 193 | *s &= ~SIGNATURE_MASK; |
| 194 | *s |= OPEN_BRACKET_SIG; // signature for '[' |
| 195 | } |
| 196 | *last = s; |
| 197 | return tok; |
| 198 | } |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 199 | adjust = peek - s; |
| 200 | if (adjust > *len) { |
| 201 | adjust = *len; |
| 202 | } |
| 203 | *sublen += adjust; |
| 204 | *len -= adjust; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 205 | s = peek; |
| 206 | break; |
| 207 | } |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 208 | ++*sublen; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 209 | } |
Mark Salyzyn | 618d0de | 2015-07-13 10:19:34 -0700 | [diff] [blame] | 210 | // NOTREACHED |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 211 | } |
| 212 | |
Mark Salyzyn | 10b82b6 | 2015-12-28 15:33:01 -0800 | [diff] [blame] | 213 | log_time LogKlog::correction = |
| 214 | (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTONIC)) |
| 215 | ? log_time::EPOCH |
| 216 | : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC)); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 217 | |
Mark Salyzyn | 7718778 | 2015-05-12 15:21:31 -0700 | [diff] [blame] | 218 | LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) : |
| 219 | SocketListener(fdRead, false), |
| 220 | logbuf(buf), |
| 221 | reader(reader), |
| 222 | signature(CLOCK_MONOTONIC), |
Mark Salyzyn | 7718778 | 2015-05-12 15:21:31 -0700 | [diff] [blame] | 223 | initialized(false), |
| 224 | enableLogging(true), |
| 225 | auditd(auditd) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 226 | static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n"; |
| 227 | char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4]; |
| 228 | snprintf(buffer, sizeof(buffer), klogd_message, priority_message, |
| 229 | signature.nsec()); |
| 230 | write(fdWrite, buffer, strlen(buffer)); |
| 231 | } |
| 232 | |
| 233 | bool LogKlog::onDataAvailable(SocketClient *cli) { |
| 234 | if (!initialized) { |
| 235 | prctl(PR_SET_NAME, "logd.klogd"); |
| 236 | initialized = true; |
| 237 | enableLogging = false; |
| 238 | } |
| 239 | |
| 240 | char buffer[LOGGER_ENTRY_MAX_PAYLOAD]; |
| 241 | size_t len = 0; |
| 242 | |
| 243 | for(;;) { |
| 244 | ssize_t retval = 0; |
| 245 | if ((sizeof(buffer) - 1 - len) > 0) { |
| 246 | retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len); |
| 247 | } |
| 248 | if ((retval == 0) && (len == 0)) { |
| 249 | break; |
| 250 | } |
| 251 | if (retval < 0) { |
| 252 | return false; |
| 253 | } |
| 254 | len += retval; |
| 255 | bool full = len == (sizeof(buffer) - 1); |
| 256 | char *ep = buffer + len; |
| 257 | *ep = '\0'; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 258 | size_t sublen; |
Mark Salyzyn | 2c3b300 | 2015-05-22 15:23:44 -0700 | [diff] [blame] | 259 | for(char *ptr = NULL, *tok = buffer; |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 260 | ((tok = log_strntok_r(tok, &len, &ptr, &sublen))); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 261 | tok = NULL) { |
Mark Salyzyn | ea1a241 | 2015-09-02 07:39:53 -0700 | [diff] [blame] | 262 | if (((tok + sublen) >= ep) && (retval != 0) && full) { |
| 263 | memmove(buffer, tok, sublen); |
| 264 | len = sublen; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 265 | break; |
| 266 | } |
| 267 | if (*tok) { |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 268 | log(tok, sublen); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 269 | } |
| 270 | } |
| 271 | } |
| 272 | |
| 273 | return true; |
| 274 | } |
| 275 | |
| 276 | |
| 277 | void LogKlog::calculateCorrection(const log_time &monotonic, |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 278 | const char *real_string, |
| 279 | size_t len) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 280 | log_time real; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 281 | const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC"); |
Mark Salyzyn | 10b82b6 | 2015-12-28 15:33:01 -0800 | [diff] [blame] | 282 | if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 283 | return; |
| 284 | } |
| 285 | // kernel report UTC, log_time::strptime is localtime from calendar. |
| 286 | // Bionic and liblog strptime does not support %z or %Z to pick up |
| 287 | // timezone so we are calculating our own correction. |
| 288 | time_t now = real.tv_sec; |
| 289 | struct tm tm; |
| 290 | memset(&tm, 0, sizeof(tm)); |
| 291 | tm.tm_isdst = -1; |
| 292 | localtime_r(&now, &tm); |
Mark Salyzyn | ff8b8e8 | 2015-12-30 13:46:07 -0800 | [diff] [blame] | 293 | if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > (long)real.tv_sec)) { |
Mark Salyzyn | 10b82b6 | 2015-12-28 15:33:01 -0800 | [diff] [blame] | 294 | real = log_time::EPOCH; |
| 295 | } else { |
| 296 | real.tv_sec += tm.tm_gmtoff; |
| 297 | } |
| 298 | if (monotonic > real) { |
| 299 | correction = log_time::EPOCH; |
| 300 | } else { |
| 301 | correction = real - monotonic; |
| 302 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 303 | } |
| 304 | |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 305 | static const char suspendStr[] = "PM: suspend entry "; |
| 306 | static const char resumeStr[] = "PM: suspend exit "; |
| 307 | static const char suspendedStr[] = "Suspended for "; |
| 308 | |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 309 | const char* android::strnstr(const char* s, size_t len, const char* needle) { |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 310 | char c; |
| 311 | |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 312 | if (!len) return NULL; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 313 | if ((c = *needle++) != 0) { |
| 314 | size_t needleLen = strlen(needle); |
| 315 | do { |
| 316 | do { |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 317 | if (len <= needleLen) return NULL; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 318 | --len; |
| 319 | } while (*s++ != c); |
Mark Salyzyn | 0eeb06b | 2016-12-02 10:08:48 -0800 | [diff] [blame] | 320 | } while (fastcmp<memcmp>(s, needle, needleLen)); |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 321 | s--; |
| 322 | } |
| 323 | return s; |
| 324 | } |
| 325 | |
| 326 | void LogKlog::sniffTime(log_time &now, |
| 327 | const char **buf, size_t len, |
| 328 | bool reverse) { |
| 329 | const char *cp = now.strptime(*buf, "[ %s.%q]"); |
| 330 | if (cp && (cp >= &(*buf)[len])) { |
| 331 | cp = NULL; |
| 332 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 333 | if (cp) { |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 334 | static const char healthd[] = "healthd"; |
| 335 | static const char battery[] = ": battery "; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 336 | |
Mark Salyzyn | 10b82b6 | 2015-12-28 15:33:01 -0800 | [diff] [blame] | 337 | len -= cp - *buf; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 338 | if (len && isspace(*cp)) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 339 | ++cp; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 340 | --len; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 341 | } |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 342 | *buf = cp; |
| 343 | |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 344 | if (isMonotonic()) { |
| 345 | return; |
| 346 | } |
| 347 | |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 348 | const char* b; |
| 349 | if (((b = android::strnstr(cp, len, suspendStr))) |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 350 | && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { |
| 351 | len -= b - cp; |
| 352 | calculateCorrection(now, b, len); |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 353 | } else if (((b = android::strnstr(cp, len, resumeStr))) |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 354 | && ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) { |
| 355 | len -= b - cp; |
| 356 | calculateCorrection(now, b, len); |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 357 | } else if (((b = android::strnstr(cp, len, healthd))) |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 358 | && ((size_t)((b += sizeof(healthd) - 1) - cp) < len) |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 359 | && ((b = android::strnstr(b, len -= b - cp, battery))) |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 360 | && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) { |
Mark Salyzyn | 10b82b6 | 2015-12-28 15:33:01 -0800 | [diff] [blame] | 361 | // NB: healthd is roughly 150us late, so we use it instead to |
| 362 | // trigger a check for ntp-induced or hardware clock drift. |
| 363 | log_time real(CLOCK_REALTIME); |
| 364 | log_time mono(CLOCK_MONOTONIC); |
| 365 | correction = (real < mono) ? log_time::EPOCH : (real - mono); |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 366 | } else if (((b = android::strnstr(cp, len, suspendedStr))) |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 367 | && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { |
| 368 | len -= b - cp; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 369 | log_time real; |
| 370 | char *endp; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 371 | real.tv_sec = strtol(b, &endp, 10); |
| 372 | if ((*endp == '.') && ((size_t)(endp - b) < len)) { |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 373 | unsigned long multiplier = NS_PER_SEC; |
| 374 | real.tv_nsec = 0; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 375 | len -= endp - b; |
| 376 | while (--len && isdigit(*++endp) && (multiplier /= 10)) { |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 377 | real.tv_nsec += (*endp - '0') * multiplier; |
| 378 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 379 | if (reverse) { |
Mark Salyzyn | 10b82b6 | 2015-12-28 15:33:01 -0800 | [diff] [blame] | 380 | if (real > correction) { |
| 381 | correction = log_time::EPOCH; |
| 382 | } else { |
| 383 | correction -= real; |
| 384 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 385 | } else { |
| 386 | correction += real; |
| 387 | } |
| 388 | } |
| 389 | } |
| 390 | |
| 391 | convertMonotonicToReal(now); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 392 | } else { |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 393 | if (isMonotonic()) { |
| 394 | now = log_time(CLOCK_MONOTONIC); |
| 395 | } else { |
| 396 | now = log_time(CLOCK_REALTIME); |
| 397 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 398 | } |
| 399 | } |
| 400 | |
Mark Salyzyn | 0b4a63d | 2016-07-15 08:54:03 -0700 | [diff] [blame] | 401 | pid_t LogKlog::sniffPid(const char **buf, size_t len) { |
| 402 | const char *cp = *buf; |
| 403 | // HTC kernels with modified printk "c0 1648 " |
| 404 | if ((len > 9) && |
| 405 | (cp[0] == 'c') && |
| 406 | isdigit(cp[1]) && |
| 407 | (isdigit(cp[2]) || (cp[2] == ' ')) && |
| 408 | (cp[3] == ' ')) { |
| 409 | bool gotDigit = false; |
| 410 | int i; |
| 411 | for (i = 4; i < 9; ++i) { |
| 412 | if (isdigit(cp[i])) { |
| 413 | gotDigit = true; |
| 414 | } else if (gotDigit || (cp[i] != ' ')) { |
| 415 | break; |
| 416 | } |
| 417 | } |
| 418 | if ((i == 9) && (cp[i] == ' ')) { |
| 419 | int pid = 0; |
| 420 | char dummy; |
| 421 | if (sscanf(cp + 4, "%d%c", &pid, &dummy) == 2) { |
| 422 | *buf = cp + 10; // skip-it-all |
| 423 | return pid; |
| 424 | } |
| 425 | } |
| 426 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 427 | while (len) { |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 428 | // Mediatek kernels with modified printk |
| 429 | if (*cp == '[') { |
| 430 | int pid = 0; |
| 431 | char dummy; |
| 432 | if (sscanf(cp, "[%d:%*[a-z_./0-9:A-Z]]%c", &pid, &dummy) == 2) { |
| 433 | return pid; |
| 434 | } |
| 435 | break; // Only the first one |
| 436 | } |
| 437 | ++cp; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 438 | --len; |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 439 | } |
| 440 | return 0; |
| 441 | } |
| 442 | |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 443 | // kernel log prefix, convert to a kernel log priority number |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 444 | static int parseKernelPrio(const char **buf, size_t len) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 445 | int pri = LOG_USER | LOG_INFO; |
| 446 | const char *cp = *buf; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 447 | if (len && (*cp == '<')) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 448 | pri = 0; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 449 | while(--len && isdigit(*++cp)) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 450 | pri = (pri * 10) + *cp - '0'; |
| 451 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 452 | if (len && (*cp == '>')) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 453 | ++cp; |
| 454 | } else { |
| 455 | cp = *buf; |
| 456 | pri = LOG_USER | LOG_INFO; |
| 457 | } |
| 458 | *buf = cp; |
| 459 | } |
| 460 | return pri; |
| 461 | } |
| 462 | |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 463 | // Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a |
| 464 | // compensated start time. |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 465 | void LogKlog::synchronize(const char* buf, size_t len) { |
| 466 | const char* cp = android::strnstr(buf, len, suspendStr); |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 467 | if (!cp) { |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 468 | cp = android::strnstr(buf, len, resumeStr); |
| 469 | if (!cp) return; |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 470 | } else { |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 471 | const char* rp = android::strnstr(buf, len, resumeStr); |
| 472 | if (rp && (rp < cp)) cp = rp; |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 473 | } |
| 474 | |
| 475 | do { |
| 476 | --cp; |
| 477 | } while ((cp > buf) && (*cp != '\n')); |
| 478 | if (*cp == '\n') { |
| 479 | ++cp; |
| 480 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 481 | parseKernelPrio(&cp, len - (cp - buf)); |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 482 | |
| 483 | log_time now; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 484 | sniffTime(now, &cp, len - (cp - buf), true); |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 485 | |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 486 | const char* suspended = android::strnstr(buf, len, suspendedStr); |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 487 | if (!suspended || (suspended > cp)) { |
| 488 | return; |
| 489 | } |
| 490 | cp = suspended; |
| 491 | |
| 492 | do { |
| 493 | --cp; |
| 494 | } while ((cp > buf) && (*cp != '\n')); |
| 495 | if (*cp == '\n') { |
| 496 | ++cp; |
| 497 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 498 | parseKernelPrio(&cp, len - (cp - buf)); |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 499 | |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 500 | sniffTime(now, &cp, len - (cp - buf), true); |
Mark Salyzyn | 2d159bf | 2015-09-01 13:09:23 -0700 | [diff] [blame] | 501 | } |
| 502 | |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 503 | // Convert kernel log priority number into an Android Logger priority number |
| 504 | static int convertKernelPrioToAndroidPrio(int pri) { |
| 505 | switch(pri & LOG_PRIMASK) { |
| 506 | case LOG_EMERG: |
| 507 | // FALLTHRU |
| 508 | case LOG_ALERT: |
| 509 | // FALLTHRU |
| 510 | case LOG_CRIT: |
| 511 | return ANDROID_LOG_FATAL; |
| 512 | |
| 513 | case LOG_ERR: |
| 514 | return ANDROID_LOG_ERROR; |
| 515 | |
| 516 | case LOG_WARNING: |
| 517 | return ANDROID_LOG_WARN; |
| 518 | |
| 519 | default: |
| 520 | // FALLTHRU |
| 521 | case LOG_NOTICE: |
| 522 | // FALLTHRU |
| 523 | case LOG_INFO: |
| 524 | break; |
| 525 | |
| 526 | case LOG_DEBUG: |
| 527 | return ANDROID_LOG_DEBUG; |
| 528 | } |
| 529 | |
| 530 | return ANDROID_LOG_INFO; |
| 531 | } |
| 532 | |
Mark Salyzyn | 47dba71 | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 533 | static const char *strnrchr(const char *s, size_t len, char c) { |
| 534 | const char *save = NULL; |
| 535 | for (;len; ++s, len--) { |
| 536 | if (*s == c) { |
| 537 | save = s; |
| 538 | } |
| 539 | } |
| 540 | return save; |
| 541 | } |
| 542 | |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 543 | // |
| 544 | // log a message into the kernel log buffer |
| 545 | // |
| 546 | // Filter rules to parse <PRI> <TIME> <tag> and <message> in order for |
| 547 | // them to appear correct in the logcat output: |
| 548 | // |
| 549 | // LOG_KERN (0): |
| 550 | // <PRI>[<TIME>] <tag> ":" <message> |
| 551 | // <PRI>[<TIME>] <tag> <tag> ":" <message> |
| 552 | // <PRI>[<TIME>] <tag> <tag>_work ":" <message> |
| 553 | // <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message> |
| 554 | // <PRI>[<TIME>] <tag> '<tag><num>' ":" <message> |
| 555 | // <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message> |
| 556 | // (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message> |
| 557 | // <PRI>[<TIME>] "[INFO]"<tag> : <message> |
| 558 | // <PRI>[<TIME>] "------------[ cut here ]------------" (?) |
| 559 | // <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---" (?) |
| 560 | // LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS |
| 561 | // LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP: |
| 562 | // <PRI+TAG>[<TIME>] (see sys/syslog.h) |
| 563 | // Observe: |
| 564 | // Minimum tag length = 3 NB: drops things like r5:c00bbadf, but allow PM: |
| 565 | // Maximum tag words = 2 |
| 566 | // Maximum tag length = 16 NB: we are thinking of how ugly logcat can get. |
| 567 | // Not a Tag if there is no message content. |
| 568 | // leading additional spaces means no tag, inherit last tag. |
| 569 | // Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:" |
| 570 | // Drop: |
| 571 | // empty messages |
| 572 | // messages with ' audit(' in them if auditd is running |
| 573 | // logd.klogd: |
| 574 | // return -1 if message logd.klogd: <signature> |
| 575 | // |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 576 | int LogKlog::log(const char* buf, size_t len) { |
| 577 | if (auditd && android::strnstr(buf, len, " audit(")) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 578 | return 0; |
| 579 | } |
| 580 | |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 581 | const char* p = buf; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 582 | int pri = parseKernelPrio(&p, len); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 583 | |
| 584 | log_time now; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 585 | sniffTime(now, &p, len - (p - buf), false); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 586 | |
| 587 | // sniff for start marker |
| 588 | const char klogd_message[] = "logd.klogd: "; |
Mark Salyzyn | a2c0222 | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 589 | const char* start = android::strnstr(p, len - (p - buf), klogd_message); |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 590 | if (start) { |
| 591 | uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 592 | if (sig == signature.nsec()) { |
| 593 | if (initialized) { |
| 594 | enableLogging = true; |
| 595 | } else { |
| 596 | enableLogging = false; |
| 597 | } |
| 598 | return -1; |
| 599 | } |
| 600 | return 0; |
| 601 | } |
| 602 | |
| 603 | if (!enableLogging) { |
| 604 | return 0; |
| 605 | } |
| 606 | |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 607 | // Parse pid, tid and uid |
Mark Salyzyn | 0b4a63d | 2016-07-15 08:54:03 -0700 | [diff] [blame] | 608 | const pid_t pid = sniffPid(&p, len - (p - buf)); |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 609 | const pid_t tid = pid; |
Mark Salyzyn | 83b2478 | 2016-08-11 16:07:10 -0700 | [diff] [blame] | 610 | uid_t uid = AID_ROOT; |
| 611 | if (pid) { |
| 612 | logbuf->lock(); |
| 613 | uid = logbuf->pidToUid(pid); |
| 614 | logbuf->unlock(); |
| 615 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 616 | |
| 617 | // Parse (rules at top) to pull out a tag from the incoming kernel message. |
| 618 | // Some may view the following as an ugly heuristic, the desire is to |
| 619 | // beautify the kernel logs into an Android Logging format; the goal is |
| 620 | // admirable but costly. |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 621 | while ((p < &buf[len]) && (isspace(*p) || !*p)) { |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 622 | ++p; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 623 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 624 | if (p >= &buf[len]) { // timestamp, no content |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 625 | return 0; |
| 626 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 627 | start = p; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 628 | const char *tag = ""; |
| 629 | const char *etag = tag; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 630 | size_t taglen = len - (p - buf); |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 631 | const char *bt = p; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 632 | |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 633 | static const char infoBrace[] = "[INFO]"; |
| 634 | static const size_t infoBraceLen = strlen(infoBrace); |
Mark Salyzyn | 0eeb06b | 2016-12-02 10:08:48 -0800 | [diff] [blame] | 635 | if ((taglen >= infoBraceLen) && !fastcmp<strncmp>(p, infoBrace, infoBraceLen)) { |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 636 | // <PRI>[<TIME>] "[INFO]"<tag> ":" message |
| 637 | bt = p + infoBraceLen; |
| 638 | taglen -= infoBraceLen; |
| 639 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 640 | |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 641 | const char *et; |
| 642 | for (et = bt; taglen && *et && (*et != ':') && !isspace(*et); ++et, --taglen) { |
| 643 | // skip ':' within [ ... ] |
| 644 | if (*et == '[') { |
| 645 | while (taglen && *et && *et != ']') { |
| 646 | ++et; |
| 647 | --taglen; |
| 648 | } |
| 649 | if (!taglen) { |
| 650 | break; |
| 651 | } |
| 652 | } |
| 653 | } |
| 654 | const char *cp; |
| 655 | for (cp = et; taglen && isspace(*cp); ++cp, --taglen); |
| 656 | |
| 657 | // Validate tag |
| 658 | size_t size = et - bt; |
| 659 | if (taglen && size) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 660 | if (*cp == ':') { |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 661 | // ToDo: handle case insensitive colon separated logging stutter: |
| 662 | // <tag> : <tag>: ... |
| 663 | |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 664 | // One Word |
| 665 | tag = bt; |
| 666 | etag = et; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 667 | p = cp + 1; |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 668 | } else if ((taglen > size) && (tolower(*bt) == tolower(*cp))) { |
| 669 | // clean up any tag stutter |
Mark Salyzyn | 0eeb06b | 2016-12-02 10:08:48 -0800 | [diff] [blame] | 670 | if (!fastcmp<strncasecmp>(bt + 1, cp + 1, size - 1)) { // no match |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 671 | // <PRI>[<TIME>] <tag> <tag> : message |
| 672 | // <PRI>[<TIME>] <tag> <tag>: message |
| 673 | // <PRI>[<TIME>] <tag> '<tag>.<num>' : message |
| 674 | // <PRI>[<TIME>] <tag> '<tag><num>' : message |
| 675 | // <PRI>[<TIME>] <tag> '<tag><stuff>' : message |
| 676 | const char *b = cp; |
| 677 | cp += size; |
| 678 | taglen -= size; |
| 679 | while (--taglen && !isspace(*++cp) && (*cp != ':')); |
| 680 | const char *e; |
| 681 | for (e = cp; taglen && isspace(*cp); ++cp, --taglen); |
| 682 | if (taglen && (*cp == ':')) { |
| 683 | tag = b; |
| 684 | etag = e; |
| 685 | p = cp + 1; |
| 686 | } |
| 687 | } else { |
| 688 | // what about <PRI>[<TIME>] <tag>_host '<tag><stuff>' : message |
| 689 | static const char host[] = "_host"; |
| 690 | static const size_t hostlen = strlen(host); |
| 691 | if ((size > hostlen) && |
Mark Salyzyn | 0eeb06b | 2016-12-02 10:08:48 -0800 | [diff] [blame] | 692 | !fastcmp<strncmp>(bt + size - hostlen, host, hostlen) && |
| 693 | !fastcmp<strncmp>(bt + 1, cp + 1, size - hostlen - 1)) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 694 | const char *b = cp; |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 695 | cp += size - hostlen; |
| 696 | taglen -= size - hostlen; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 697 | if (*cp == '.') { |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 698 | while (--taglen && !isspace(*++cp) && (*cp != ':')); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 699 | const char *e; |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 700 | for (e = cp; taglen && isspace(*cp); ++cp, --taglen); |
| 701 | if (taglen && (*cp == ':')) { |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 702 | tag = b; |
| 703 | etag = e; |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 704 | p = cp + 1; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 705 | } |
| 706 | } |
| 707 | } else { |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 708 | goto twoWord; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 709 | } |
| 710 | } |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 711 | } else { |
| 712 | // <PRI>[<TIME>] <tag> <stuff>' : message |
| 713 | twoWord: while (--taglen && !isspace(*++cp) && (*cp != ':')); |
| 714 | const char *e; |
| 715 | for (e = cp; taglen && isspace(*cp); ++cp, --taglen); |
| 716 | // Two words |
| 717 | if (taglen && (*cp == ':')) { |
| 718 | tag = bt; |
| 719 | etag = e; |
| 720 | p = cp + 1; |
| 721 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 722 | } |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 723 | } // else no tag |
| 724 | |
| 725 | static const char cpu[] = "CPU"; |
| 726 | static const size_t cpuLen = strlen(cpu); |
| 727 | static const char warning[] = "WARNING"; |
| 728 | static const size_t warningLen = strlen(warning); |
| 729 | static const char error[] = "ERROR"; |
| 730 | static const size_t errorLen = strlen(error); |
| 731 | static const char info[] = "INFO"; |
| 732 | static const size_t infoLen = strlen(info); |
| 733 | |
| 734 | size = etag - tag; |
| 735 | if ((size <= 1) |
| 736 | // register names like x9 |
| 737 | || ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1]))) |
| 738 | // register names like x18 but not driver names like en0 |
| 739 | || ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2]))) |
| 740 | // blacklist |
Mark Salyzyn | 0eeb06b | 2016-12-02 10:08:48 -0800 | [diff] [blame] | 741 | || ((size == cpuLen) && !fastcmp<strncmp>(tag, cpu, cpuLen)) |
| 742 | || ((size == warningLen) && !fastcmp<strncasecmp>(tag, warning, warningLen)) |
| 743 | || ((size == errorLen) && !fastcmp<strncasecmp>(tag, error, errorLen)) |
| 744 | || ((size == infoLen) && !fastcmp<strncasecmp>(tag, info, infoLen))) { |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 745 | p = start; |
| 746 | etag = tag = ""; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 747 | } |
Mark Salyzyn | a146a77 | 2016-08-05 08:16:37 -0700 | [diff] [blame] | 748 | |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 749 | // Suppress additional stutter in tag: |
| 750 | // eg: [143:healthd]healthd -> [143:healthd] |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 751 | taglen = etag - tag; |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 752 | // Mediatek-special printk induced stutter |
Mark Salyzyn | 47dba71 | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 753 | const char *mp = strnrchr(tag, ']', taglen); |
| 754 | if (mp && (++mp < etag)) { |
| 755 | size_t s = etag - mp; |
Mark Salyzyn | 0eeb06b | 2016-12-02 10:08:48 -0800 | [diff] [blame] | 756 | if (((s + s) < taglen) && !fastcmp<memcmp>(mp, mp - 1 - s, s)) { |
Mark Salyzyn | 47dba71 | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 757 | taglen = mp - tag; |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 758 | } |
| 759 | } |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 760 | // Deal with sloppy and simplistic harmless p = cp + 1 etc above. |
| 761 | if (len < (size_t)(p - buf)) { |
| 762 | p = &buf[len]; |
| 763 | } |
Mark Salyzyn | ee49c6a | 2015-06-12 14:59:42 -0700 | [diff] [blame] | 764 | // skip leading space |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 765 | while ((p < &buf[len]) && (isspace(*p) || !*p)) { |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 766 | ++p; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 767 | } |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 768 | // truncate trailing space or nuls |
| 769 | size_t b = len - (p - buf); |
| 770 | while (b && (isspace(p[b-1]) || !p[b-1])) { |
Mark Salyzyn | ee49c6a | 2015-06-12 14:59:42 -0700 | [diff] [blame] | 771 | --b; |
| 772 | } |
| 773 | // trick ... allow tag with empty content to be logged. log() drops empty |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 774 | if (!b && taglen) { |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 775 | p = " "; |
Mark Salyzyn | ee49c6a | 2015-06-12 14:59:42 -0700 | [diff] [blame] | 776 | b = 1; |
| 777 | } |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 778 | // paranoid sanity check, can not happen ... |
Mark Salyzyn | ddda212 | 2015-10-02 09:22:52 -0700 | [diff] [blame] | 779 | if (b > LOGGER_ENTRY_MAX_PAYLOAD) { |
| 780 | b = LOGGER_ENTRY_MAX_PAYLOAD; |
| 781 | } |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 782 | if (taglen > LOGGER_ENTRY_MAX_PAYLOAD) { |
| 783 | taglen = LOGGER_ENTRY_MAX_PAYLOAD; |
| 784 | } |
| 785 | // calculate buffer copy requirements |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 786 | size_t n = 1 + taglen + 1 + b + 1; |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 787 | // paranoid sanity check, first two just can not happen ... |
| 788 | if ((taglen > n) || (b > n) || (n > USHRT_MAX)) { |
| 789 | return -EINVAL; |
Mark Salyzyn | 47dba71 | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 790 | } |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 791 | |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 792 | // Careful. |
| 793 | // We are using the stack to house the log buffer for speed reasons. |
| 794 | // If we malloc'd this buffer, we could get away without n's USHRT_MAX |
| 795 | // test above, but we would then required a max(n, USHRT_MAX) as |
| 796 | // truncating length argument to logbuf->log() below. Gain is protection |
| 797 | // of stack sanity and speedup, loss is truncated long-line content. |
Mark Salyzyn | ddda212 | 2015-10-02 09:22:52 -0700 | [diff] [blame] | 798 | char newstr[n]; |
Mark Salyzyn | 47dba71 | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 799 | char *np = newstr; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 800 | |
| 801 | // Convert priority into single-byte Android logger priority |
| 802 | *np = convertKernelPrioToAndroidPrio(pri); |
| 803 | ++np; |
| 804 | |
| 805 | // Copy parsed tag following priority |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 806 | memcpy(np, tag, taglen); |
Mark Salyzyn | 46d159d | 2015-08-26 09:30:00 -0700 | [diff] [blame] | 807 | np += taglen; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 808 | *np = '\0'; |
| 809 | ++np; |
| 810 | |
| 811 | // Copy main message to the remainder |
Mark Salyzyn | 151beac | 2015-09-04 11:37:42 -0700 | [diff] [blame] | 812 | memcpy(np, p, b); |
Mark Salyzyn | ee49c6a | 2015-06-12 14:59:42 -0700 | [diff] [blame] | 813 | np[b] = '\0'; |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 814 | |
Mark Salyzyn | b06247d | 2015-12-04 09:32:27 -0800 | [diff] [blame] | 815 | if (!isMonotonic()) { |
| 816 | // Watch out for singular race conditions with timezone causing near |
| 817 | // integer quarter-hour jumps in the time and compensate accordingly. |
| 818 | // Entries will be temporal within near_seconds * 2. b/21868540 |
| 819 | static uint32_t vote_time[3]; |
| 820 | vote_time[2] = vote_time[1]; |
| 821 | vote_time[1] = vote_time[0]; |
| 822 | vote_time[0] = now.tv_sec; |
| 823 | |
| 824 | if (vote_time[1] && vote_time[2]) { |
| 825 | static const unsigned near_seconds = 10; |
| 826 | static const unsigned timezones_seconds = 900; |
| 827 | int diff0 = (vote_time[0] - vote_time[1]) / near_seconds; |
| 828 | unsigned abs0 = (diff0 < 0) ? -diff0 : diff0; |
| 829 | int diff1 = (vote_time[1] - vote_time[2]) / near_seconds; |
| 830 | unsigned abs1 = (diff1 < 0) ? -diff1 : diff1; |
| 831 | if ((abs1 <= 1) && // last two were in agreement on timezone |
| 832 | ((abs0 + 1) % (timezones_seconds / near_seconds)) <= 2) { |
| 833 | abs0 = (abs0 + 1) / (timezones_seconds / near_seconds) * |
| 834 | timezones_seconds; |
| 835 | now.tv_sec -= (diff0 < 0) ? -abs0 : abs0; |
| 836 | } |
| 837 | } |
| 838 | } |
| 839 | |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 840 | // Log message |
Mark Salyzyn | eb29808 | 2015-11-10 15:56:41 -0800 | [diff] [blame] | 841 | int rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr, |
| 842 | (unsigned short) n); |
Mark Salyzyn | ae4d928 | 2014-10-15 08:49:39 -0700 | [diff] [blame] | 843 | |
| 844 | // notify readers |
| 845 | if (!rc) { |
| 846 | reader->notifyNewLog(); |
| 847 | } |
| 848 | |
| 849 | return rc; |
| 850 | } |