1 /* 2 * Copyright (C) 2012-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 <stdio.h> 20 #include <string.h> 21 #include <sys/user.h> 22 #include <time.h> 23 #include <unistd.h> 24 25 #include <unordered_map> 26 27 #include <cutils/properties.h> 28 #include <log/logger.h> 29 30 #include "LogBuffer.h" 31 #include "LogReader.h" 32 33 // Default 34 #define LOG_BUFFER_SIZE (256 * 1024) // Tuned on a per-platform basis here? 35 #define log_buffer_size(id) mMaxSize[id] 36 #define LOG_BUFFER_MIN_SIZE (64 * 1024UL) 37 #define LOG_BUFFER_MAX_SIZE (256 * 1024 * 1024UL) 38 39 static bool valid_size(unsigned long value) { 40 if ((value < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < value)) { 41 return false; 42 } 43 44 long pages = sysconf(_SC_PHYS_PAGES); 45 if (pages < 1) { 46 return true; 47 } 48 49 long pagesize = sysconf(_SC_PAGESIZE); 50 if (pagesize <= 1) { 51 pagesize = PAGE_SIZE; 52 } 53 54 // maximum memory impact a somewhat arbitrary ~3% 55 pages = (pages + 31) / 32; 56 unsigned long maximum = pages * pagesize; 57 58 if ((maximum < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < maximum)) { 59 return true; 60 } 61 62 return value <= maximum; 63 } 64 65 static unsigned long property_get_size(const char *key) { 66 char property[PROPERTY_VALUE_MAX]; 67 property_get(key, property, ""); 68 69 char *cp; 70 unsigned long value = strtoul(property, &cp, 10); 71 72 switch(*cp) { 73 case 'm': 74 case 'M': 75 value *= 1024; 76 /* FALLTHRU */ 77 case 'k': 78 case 'K': 79 value *= 1024; 80 /* FALLTHRU */ 81 case '\0': 82 break; 83 84 default: 85 value = 0; 86 } 87 88 if (!valid_size(value)) { 89 value = 0; 90 } 91 92 return value; 93 } 94 95 void LogBuffer::init() { 96 static const char global_tuneable[] = "persist.logd.size"; // Settings App 97 static const char global_default[] = "ro.logd.size"; // BoardConfig.mk 98 99 unsigned long default_size = property_get_size(global_tuneable); 100 if (!default_size) { 101 default_size = property_get_size(global_default); 102 } 103 104 log_id_for_each(i) { 105 char key[PROP_NAME_MAX]; 106 107 snprintf(key, sizeof(key), "%s.%s", 108 global_tuneable, android_log_id_to_name(i)); 109 unsigned long property_size = property_get_size(key); 110 111 if (!property_size) { 112 snprintf(key, sizeof(key), "%s.%s", 113 global_default, android_log_id_to_name(i)); 114 property_size = property_get_size(key); 115 } 116 117 if (!property_size) { 118 property_size = default_size; 119 } 120 121 if (!property_size) { 122 property_size = LOG_BUFFER_SIZE; 123 } 124 125 if (setSize(i, property_size)) { 126 setSize(i, LOG_BUFFER_MIN_SIZE); 127 } 128 } 129 } 130 131 LogBuffer::LogBuffer(LastLogTimes *times) : mTimes(*times) { 132 pthread_mutex_init(&mLogElementsLock, NULL); 133 134 init(); 135 } 136 137 int LogBuffer::log(log_id_t log_id, log_time realtime, 138 uid_t uid, pid_t pid, pid_t tid, 139 const char *msg, unsigned short len) { 140 if ((log_id >= LOG_ID_MAX) || (log_id < 0)) { 141 return -EINVAL; 142 } 143 144 LogBufferElement *elem = new LogBufferElement(log_id, realtime, 145 uid, pid, tid, msg, len); 146 int prio = ANDROID_LOG_INFO; 147 const char *tag = NULL; 148 if (log_id == LOG_ID_EVENTS) { 149 tag = android::tagToName(elem->getTag()); 150 } else { 151 prio = *msg; 152 tag = msg + 1; 153 } 154 if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) { 155 // Log traffic received to total 156 pthread_mutex_lock(&mLogElementsLock); 157 stats.add(elem); 158 stats.subtract(elem); 159 pthread_mutex_unlock(&mLogElementsLock); 160 delete elem; 161 return -EACCES; 162 } 163 164 pthread_mutex_lock(&mLogElementsLock); 165 166 // Insert elements in time sorted order if possible 167 // NB: if end is region locked, place element at end of list 168 LogBufferElementCollection::iterator it = mLogElements.end(); 169 LogBufferElementCollection::iterator last = it; 170 while (last != mLogElements.begin()) { 171 --it; 172 if ((*it)->getRealTime() <= realtime) { 173 break; 174 } 175 last = it; 176 } 177 178 if (last == mLogElements.end()) { 179 mLogElements.push_back(elem); 180 } else { 181 uint64_t end = 1; 182 bool end_set = false; 183 bool end_always = false; 184 185 LogTimeEntry::lock(); 186 187 LastLogTimes::iterator t = mTimes.begin(); 188 while(t != mTimes.end()) { 189 LogTimeEntry *entry = (*t); 190 if (entry->owned_Locked()) { 191 if (!entry->mNonBlock) { 192 end_always = true; 193 break; 194 } 195 if (!end_set || (end <= entry->mEnd)) { 196 end = entry->mEnd; 197 end_set = true; 198 } 199 } 200 t++; 201 } 202 203 if (end_always 204 || (end_set && (end >= (*last)->getSequence()))) { 205 mLogElements.push_back(elem); 206 } else { 207 mLogElements.insert(last,elem); 208 } 209 210 LogTimeEntry::unlock(); 211 } 212 213 stats.add(elem); 214 maybePrune(log_id); 215 pthread_mutex_unlock(&mLogElementsLock); 216 217 return len; 218 } 219 220 // If we're using more than 256K of memory for log entries, prune 221 // at least 10% of the log entries. 222 // 223 // mLogElementsLock must be held when this function is called. 224 void LogBuffer::maybePrune(log_id_t id) { 225 size_t sizes = stats.sizes(id); 226 if (sizes > log_buffer_size(id)) { 227 size_t sizeOver90Percent = sizes - ((log_buffer_size(id) * 9) / 10); 228 size_t elements = stats.elements(id); 229 unsigned long pruneRows = elements * sizeOver90Percent / sizes; 230 elements /= 10; 231 if (pruneRows <= elements) { 232 pruneRows = elements; 233 } 234 prune(id, pruneRows); 235 } 236 } 237 238 LogBufferElementCollection::iterator LogBuffer::erase(LogBufferElementCollection::iterator it) { 239 LogBufferElement *e = *it; 240 241 it = mLogElements.erase(it); 242 stats.subtract(e); 243 delete e; 244 245 return it; 246 } 247 248 // Define a temporary mechanism to report the last LogBufferElement pointer 249 // for the specified uid, pid and tid. Used below to help merge-sort when 250 // pruning for worst UID. 251 class LogBufferElementKey { 252 const union { 253 struct { 254 uint16_t uid; 255 uint16_t pid; 256 uint16_t tid; 257 uint16_t padding; 258 } __packed; 259 uint64_t value; 260 } __packed; 261 262 public: 263 LogBufferElementKey(uid_t u, pid_t p, pid_t t):uid(u),pid(p),tid(t),padding(0) { } 264 LogBufferElementKey(uint64_t k):value(k) { } 265 266 uint64_t getKey() { return value; } 267 }; 268 269 class LogBufferElementLast { 270 271 typedef std::unordered_map<uint64_t, LogBufferElement *> LogBufferElementMap; 272 LogBufferElementMap map; 273 274 public: 275 276 bool merge(LogBufferElement *e, unsigned short dropped) { 277 LogBufferElementKey key(e->getUid(), e->getPid(), e->getTid()); 278 LogBufferElementMap::iterator it = map.find(key.getKey()); 279 if (it != map.end()) { 280 LogBufferElement *l = it->second; 281 unsigned short d = l->getDropped(); 282 if ((dropped + d) > USHRT_MAX) { 283 map.erase(it); 284 } else { 285 l->setDropped(dropped + d); 286 return true; 287 } 288 } 289 return false; 290 } 291 292 void add(LogBufferElement *e) { 293 LogBufferElementKey key(e->getUid(), e->getPid(), e->getTid()); 294 map[key.getKey()] = e; 295 } 296 297 inline void clear() { 298 map.clear(); 299 } 300 301 void clear(LogBufferElement *e) { 302 uint64_t current = e->getRealTime().nsec() 303 - (EXPIRE_RATELIMIT * NS_PER_SEC); 304 for(LogBufferElementMap::iterator it = map.begin(); it != map.end();) { 305 LogBufferElement *l = it->second; 306 if ((l->getDropped() >= EXPIRE_THRESHOLD) 307 && (current > l->getRealTime().nsec())) { 308 it = map.erase(it); 309 } else { 310 ++it; 311 } 312 } 313 } 314 315 }; 316 317 // prune "pruneRows" of type "id" from the buffer. 318 // 319 // mLogElementsLock must be held when this function is called. 320 void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { 321 LogTimeEntry *oldest = NULL; 322 323 LogTimeEntry::lock(); 324 325 // Region locked? 326 LastLogTimes::iterator t = mTimes.begin(); 327 while(t != mTimes.end()) { 328 LogTimeEntry *entry = (*t); 329 if (entry->owned_Locked() && entry->isWatching(id) 330 && (!oldest || (oldest->mStart > entry->mStart))) { 331 oldest = entry; 332 } 333 t++; 334 } 335 336 LogBufferElementCollection::iterator it; 337 338 if (caller_uid != AID_ROOT) { 339 for(it = mLogElements.begin(); it != mLogElements.end();) { 340 LogBufferElement *e = *it; 341 342 if (oldest && (oldest->mStart <= e->getSequence())) { 343 break; 344 } 345 346 if (e->getLogId() != id) { 347 ++it; 348 continue; 349 } 350 351 if (e->getUid() == caller_uid) { 352 it = erase(it); 353 pruneRows--; 354 if (pruneRows == 0) { 355 break; 356 } 357 } else { 358 ++it; 359 } 360 } 361 LogTimeEntry::unlock(); 362 return; 363 } 364 365 // prune by worst offender by uid 366 bool hasBlacklist = mPrune.naughty(); 367 while (pruneRows > 0) { 368 // recalculate the worst offender on every batched pass 369 uid_t worst = (uid_t) -1; 370 size_t worst_sizes = 0; 371 size_t second_worst_sizes = 0; 372 373 if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) { 374 std::unique_ptr<const UidEntry *[]> sorted = stats.sort(2, id); 375 376 if (sorted.get()) { 377 if (sorted[0] && sorted[1]) { 378 worst_sizes = sorted[0]->getSizes(); 379 // Calculate threshold as 12.5% of available storage 380 size_t threshold = log_buffer_size(id) / 8; 381 if (worst_sizes > threshold) { 382 worst = sorted[0]->getKey(); 383 second_worst_sizes = sorted[1]->getSizes(); 384 if (second_worst_sizes < threshold) { 385 second_worst_sizes = threshold; 386 } 387 } 388 } 389 } 390 } 391 392 // skip if we have neither worst nor naughty filters 393 if ((worst == (uid_t) -1) && !hasBlacklist) { 394 break; 395 } 396 397 bool kick = false; 398 bool leading = true; 399 LogBufferElementLast last; 400 for(it = mLogElements.begin(); it != mLogElements.end();) { 401 LogBufferElement *e = *it; 402 403 if (oldest && (oldest->mStart <= e->getSequence())) { 404 break; 405 } 406 407 if (e->getLogId() != id) { 408 ++it; 409 continue; 410 } 411 412 unsigned short dropped = e->getDropped(); 413 414 // remove any leading drops 415 if (leading && dropped) { 416 it = erase(it); 417 continue; 418 } 419 420 // merge any drops 421 if (dropped && last.merge(e, dropped)) { 422 it = mLogElements.erase(it); 423 stats.erase(e); 424 delete e; 425 continue; 426 } 427 428 if (hasBlacklist && mPrune.naughty(e)) { 429 last.clear(e); 430 it = erase(it); 431 if (dropped) { 432 continue; 433 } 434 435 pruneRows--; 436 if (pruneRows == 0) { 437 break; 438 } 439 440 if (e->getUid() == worst) { 441 kick = true; 442 if (worst_sizes < second_worst_sizes) { 443 break; 444 } 445 worst_sizes -= e->getMsgLen(); 446 } 447 continue; 448 } 449 450 if (dropped) { 451 last.add(e); 452 ++it; 453 continue; 454 } 455 456 if (e->getUid() != worst) { 457 if (leading) { 458 static const timespec too_old = { 459 EXPIRE_HOUR_THRESHOLD * 60 * 60, 0 460 }; 461 LogBufferElementCollection::iterator last; 462 last = mLogElements.end(); 463 --last; 464 if ((e->getRealTime() < ((*last)->getRealTime() - too_old)) 465 || (e->getRealTime() > (*last)->getRealTime())) { 466 break; 467 } 468 } 469 leading = false; 470 last.clear(e); 471 ++it; 472 continue; 473 } 474 475 pruneRows--; 476 if (pruneRows == 0) { 477 break; 478 } 479 480 kick = true; 481 482 unsigned short len = e->getMsgLen(); 483 484 // do not create any leading drops 485 if (leading) { 486 it = erase(it); 487 } else { 488 stats.drop(e); 489 e->setDropped(1); 490 if (last.merge(e, 1)) { 491 it = mLogElements.erase(it); 492 stats.erase(e); 493 delete e; 494 } else { 495 last.add(e); 496 ++it; 497 } 498 } 499 if (worst_sizes < second_worst_sizes) { 500 break; 501 } 502 worst_sizes -= len; 503 } 504 last.clear(); 505 506 if (!kick || !mPrune.worstUidEnabled()) { 507 break; // the following loop will ask bad clients to skip/drop 508 } 509 } 510 511 bool whitelist = false; 512 bool hasWhitelist = mPrune.nice(); 513 it = mLogElements.begin(); 514 while((pruneRows > 0) && (it != mLogElements.end())) { 515 LogBufferElement *e = *it; 516 517 if (e->getLogId() != id) { 518 it++; 519 continue; 520 } 521 522 if (oldest && (oldest->mStart <= e->getSequence())) { 523 if (whitelist) { 524 break; 525 } 526 527 if (stats.sizes(id) > (2 * log_buffer_size(id))) { 528 // kick a misbehaving log reader client off the island 529 oldest->release_Locked(); 530 } else { 531 oldest->triggerSkip_Locked(id, pruneRows); 532 } 533 break; 534 } 535 536 if (hasWhitelist && !e->getDropped() && mPrune.nice(e)) { // WhiteListed 537 whitelist = true; 538 it++; 539 continue; 540 } 541 542 it = erase(it); 543 pruneRows--; 544 } 545 546 // Do not save the whitelist if we are reader range limited 547 if (whitelist && (pruneRows > 0)) { 548 it = mLogElements.begin(); 549 while((it != mLogElements.end()) && (pruneRows > 0)) { 550 LogBufferElement *e = *it; 551 552 if (e->getLogId() != id) { 553 ++it; 554 continue; 555 } 556 557 if (oldest && (oldest->mStart <= e->getSequence())) { 558 if (stats.sizes(id) > (2 * log_buffer_size(id))) { 559 // kick a misbehaving log reader client off the island 560 oldest->release_Locked(); 561 } else { 562 oldest->triggerSkip_Locked(id, pruneRows); 563 } 564 break; 565 } 566 567 it = erase(it); 568 pruneRows--; 569 } 570 } 571 572 LogTimeEntry::unlock(); 573 } 574 575 // clear all rows of type "id" from the buffer. 576 void LogBuffer::clear(log_id_t id, uid_t uid) { 577 pthread_mutex_lock(&mLogElementsLock); 578 prune(id, ULONG_MAX, uid); 579 pthread_mutex_unlock(&mLogElementsLock); 580 } 581 582 // get the used space associated with "id". 583 unsigned long LogBuffer::getSizeUsed(log_id_t id) { 584 pthread_mutex_lock(&mLogElementsLock); 585 size_t retval = stats.sizes(id); 586 pthread_mutex_unlock(&mLogElementsLock); 587 return retval; 588 } 589 590 // set the total space allocated to "id" 591 int LogBuffer::setSize(log_id_t id, unsigned long size) { 592 // Reasonable limits ... 593 if (!valid_size(size)) { 594 return -1; 595 } 596 pthread_mutex_lock(&mLogElementsLock); 597 log_buffer_size(id) = size; 598 pthread_mutex_unlock(&mLogElementsLock); 599 return 0; 600 } 601 602 // get the total space allocated to "id" 603 unsigned long LogBuffer::getSize(log_id_t id) { 604 pthread_mutex_lock(&mLogElementsLock); 605 size_t retval = log_buffer_size(id); 606 pthread_mutex_unlock(&mLogElementsLock); 607 return retval; 608 } 609 610 uint64_t LogBuffer::flushTo( 611 SocketClient *reader, const uint64_t start, bool privileged, 612 int (*filter)(const LogBufferElement *element, void *arg), void *arg) { 613 LogBufferElementCollection::iterator it; 614 uint64_t max = start; 615 uid_t uid = reader->getUid(); 616 617 pthread_mutex_lock(&mLogElementsLock); 618 619 if (start <= 1) { 620 // client wants to start from the beginning 621 it = mLogElements.begin(); 622 } else { 623 // Client wants to start from some specified time. Chances are 624 // we are better off starting from the end of the time sorted list. 625 for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { 626 --it; 627 LogBufferElement *element = *it; 628 if (element->getSequence() <= start) { 629 it++; 630 break; 631 } 632 } 633 } 634 635 for (; it != mLogElements.end(); ++it) { 636 LogBufferElement *element = *it; 637 638 if (!privileged && (element->getUid() != uid)) { 639 continue; 640 } 641 642 if (element->getSequence() <= start) { 643 continue; 644 } 645 646 // NB: calling out to another object with mLogElementsLock held (safe) 647 if (filter) { 648 int ret = (*filter)(element, arg); 649 if (ret == false) { 650 continue; 651 } 652 if (ret != true) { 653 break; 654 } 655 } 656 657 pthread_mutex_unlock(&mLogElementsLock); 658 659 // range locking in LastLogTimes looks after us 660 max = element->flushTo(reader, this); 661 662 if (max == element->FLUSH_ERROR) { 663 return max; 664 } 665 666 pthread_mutex_lock(&mLogElementsLock); 667 } 668 pthread_mutex_unlock(&mLogElementsLock); 669 670 return max; 671 } 672 673 void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) { 674 pthread_mutex_lock(&mLogElementsLock); 675 676 stats.format(strp, uid, logMask); 677 678 pthread_mutex_unlock(&mLogElementsLock); 679 } 680