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 // for manual checking of stale entries during LogBuffer::erase() 17 //#define DEBUG_CHECK_FOR_STALE_ENTRIES 18 19 #include <ctype.h> 20 #include <endian.h> 21 #include <errno.h> 22 #include <stdio.h> 23 #include <string.h> 24 #include <sys/cdefs.h> 25 #include <sys/user.h> 26 #include <time.h> 27 #include <unistd.h> 28 29 #include <unordered_map> 30 31 #include <cutils/properties.h> 32 #include <private/android_logger.h> 33 34 #include "LogBuffer.h" 35 #include "LogKlog.h" 36 #include "LogReader.h" 37 #include "LogUtils.h" 38 39 #ifndef __predict_false 40 #define __predict_false(exp) __builtin_expect((exp) != 0, 0) 41 #endif 42 43 // Default 44 #define log_buffer_size(id) mMaxSize[id] 45 46 const log_time LogBuffer::pruneMargin(3, 0); 47 48 void LogBuffer::init() { 49 log_id_for_each(i) { 50 mLastSet[i] = false; 51 mLast[i] = mLogElements.begin(); 52 53 if (setSize(i, __android_logger_get_buffer_size(i))) { 54 setSize(i, LOG_BUFFER_MIN_SIZE); 55 } 56 } 57 bool lastMonotonic = monotonic; 58 monotonic = android_log_clockid() == CLOCK_MONOTONIC; 59 if (lastMonotonic != monotonic) { 60 // 61 // Fixup all timestamps, may not be 100% accurate, but better than 62 // throwing what we have away when we get 'surprised' by a change. 63 // In-place element fixup so no need to check reader-lock. Entries 64 // should already be in timestamp order, but we could end up with a 65 // few out-of-order entries if new monotonics come in before we 66 // are notified of the reinit change in status. A Typical example would 67 // be: 68 // --------- beginning of system 69 // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data 70 // --------- beginning of kernel 71 // 0.000000 0 0 I : Initializing cgroup subsys 72 // as the act of mounting /data would trigger persist.logd.timestamp to 73 // be corrected. 1/30 corner case YMMV. 74 // 75 pthread_mutex_lock(&mLogElementsLock); 76 LogBufferElementCollection::iterator it = mLogElements.begin(); 77 while ((it != mLogElements.end())) { 78 LogBufferElement* e = *it; 79 if (monotonic) { 80 if (!android::isMonotonic(e->mRealTime)) { 81 LogKlog::convertRealToMonotonic(e->mRealTime); 82 } 83 } else { 84 if (android::isMonotonic(e->mRealTime)) { 85 LogKlog::convertMonotonicToReal(e->mRealTime); 86 } 87 } 88 ++it; 89 } 90 pthread_mutex_unlock(&mLogElementsLock); 91 } 92 93 // We may have been triggered by a SIGHUP. Release any sleeping reader 94 // threads to dump their current content. 95 // 96 // NB: this is _not_ performed in the context of a SIGHUP, it is 97 // performed during startup, and in context of reinit administrative thread 98 LogTimeEntry::lock(); 99 100 LastLogTimes::iterator times = mTimes.begin(); 101 while (times != mTimes.end()) { 102 LogTimeEntry* entry = (*times); 103 if (entry->owned_Locked()) { 104 entry->triggerReader_Locked(); 105 } 106 times++; 107 } 108 109 LogTimeEntry::unlock(); 110 } 111 112 LogBuffer::LogBuffer(LastLogTimes* times) 113 : monotonic(android_log_clockid() == CLOCK_MONOTONIC), mTimes(*times) { 114 pthread_mutex_init(&mLogElementsLock, nullptr); 115 116 log_id_for_each(i) { 117 lastLoggedElements[i] = nullptr; 118 droppedElements[i] = nullptr; 119 } 120 121 init(); 122 } 123 124 LogBuffer::~LogBuffer() { 125 log_id_for_each(i) { 126 delete lastLoggedElements[i]; 127 delete droppedElements[i]; 128 } 129 } 130 131 enum match_type { DIFFERENT, SAME, SAME_LIBLOG }; 132 133 static enum match_type identical(LogBufferElement* elem, 134 LogBufferElement* last) { 135 // is it mostly identical? 136 // if (!elem) return DIFFERENT; 137 ssize_t lenl = elem->getMsgLen(); 138 if (lenl <= 0) return DIFFERENT; // value if this represents a chatty elem 139 // if (!last) return DIFFERENT; 140 ssize_t lenr = last->getMsgLen(); 141 if (lenr <= 0) return DIFFERENT; // value if this represents a chatty elem 142 // if (elem->getLogId() != last->getLogId()) return DIFFERENT; 143 if (elem->getUid() != last->getUid()) return DIFFERENT; 144 if (elem->getPid() != last->getPid()) return DIFFERENT; 145 if (elem->getTid() != last->getTid()) return DIFFERENT; 146 147 // last is more than a minute old, stop squashing identical messages 148 if (elem->getRealTime().nsec() > 149 (last->getRealTime().nsec() + 60 * NS_PER_SEC)) 150 return DIFFERENT; 151 152 // Identical message 153 const char* msgl = elem->getMsg(); 154 const char* msgr = last->getMsg(); 155 if (lenl == lenr) { 156 if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME; 157 // liblog tagged messages (content gets summed) 158 if ((elem->getLogId() == LOG_ID_EVENTS) && 159 (lenl == sizeof(android_log_event_int_t)) && 160 !fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_int_t) - 161 sizeof(int32_t)) && 162 (elem->getTag() == LIBLOG_LOG_TAG)) { 163 return SAME_LIBLOG; 164 } 165 } 166 167 // audit message (except sequence number) identical? 168 if (last->isBinary()) { 169 if (fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_string_t) - 170 sizeof(int32_t))) { 171 return DIFFERENT; 172 } 173 msgl += sizeof(android_log_event_string_t); 174 lenl -= sizeof(android_log_event_string_t); 175 msgr += sizeof(android_log_event_string_t); 176 lenr -= sizeof(android_log_event_string_t); 177 } 178 static const char avc[] = "): avc: "; 179 const char* avcl = android::strnstr(msgl, lenl, avc); 180 if (!avcl) return DIFFERENT; 181 lenl -= avcl - msgl; 182 const char* avcr = android::strnstr(msgr, lenr, avc); 183 if (!avcr) return DIFFERENT; 184 lenr -= avcr - msgr; 185 if (lenl != lenr) return DIFFERENT; 186 if (fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), 187 lenl - strlen(avc))) { 188 return DIFFERENT; 189 } 190 return SAME; 191 } 192 193 int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, 194 pid_t tid, const char* msg, unsigned short len) { 195 if ((log_id >= LOG_ID_MAX) || (log_id < 0)) { 196 return -EINVAL; 197 } 198 199 LogBufferElement* elem = 200 new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len); 201 if (log_id != LOG_ID_SECURITY) { 202 int prio = ANDROID_LOG_INFO; 203 const char* tag = nullptr; 204 if (log_id == LOG_ID_EVENTS) { 205 tag = tagToName(elem->getTag()); 206 } else { 207 prio = *msg; 208 tag = msg + 1; 209 } 210 if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) { 211 // Log traffic received to total 212 pthread_mutex_lock(&mLogElementsLock); 213 stats.add(elem); 214 stats.subtract(elem); 215 pthread_mutex_unlock(&mLogElementsLock); 216 delete elem; 217 return -EACCES; 218 } 219 } 220 221 pthread_mutex_lock(&mLogElementsLock); 222 LogBufferElement* currentLast = lastLoggedElements[log_id]; 223 if (currentLast) { 224 LogBufferElement* dropped = droppedElements[log_id]; 225 unsigned short count = dropped ? dropped->getDropped() : 0; 226 // 227 // State Init 228 // incoming: 229 // dropped = nullptr 230 // currentLast = nullptr; 231 // elem = incoming message 232 // outgoing: 233 // dropped = nullptr -> State 0 234 // currentLast = copy of elem 235 // log elem 236 // State 0 237 // incoming: 238 // count = 0 239 // dropped = nullptr 240 // currentLast = copy of last message 241 // elem = incoming message 242 // outgoing: if match != DIFFERENT 243 // dropped = copy of first identical message -> State 1 244 // currentLast = reference to elem 245 // break: if match == DIFFERENT 246 // dropped = nullptr -> State 0 247 // delete copy of last message (incoming currentLast) 248 // currentLast = copy of elem 249 // log elem 250 // State 1 251 // incoming: 252 // count = 0 253 // dropped = copy of first identical message 254 // currentLast = reference to last held-back incoming 255 // message 256 // elem = incoming message 257 // outgoing: if match == SAME 258 // delete copy of first identical message (dropped) 259 // dropped = reference to last held-back incoming 260 // message set to chatty count of 1 -> State 2 261 // currentLast = reference to elem 262 // outgoing: if match == SAME_LIBLOG 263 // dropped = copy of first identical message -> State 1 264 // take sum of currentLast and elem 265 // if sum overflows: 266 // log currentLast 267 // currentLast = reference to elem 268 // else 269 // delete currentLast 270 // currentLast = reference to elem, sum liblog. 271 // break: if match == DIFFERENT 272 // delete dropped 273 // dropped = nullptr -> State 0 274 // log reference to last held-back (currentLast) 275 // currentLast = copy of elem 276 // log elem 277 // State 2 278 // incoming: 279 // count = chatty count 280 // dropped = chatty message holding count 281 // currentLast = reference to last held-back incoming 282 // message. 283 // dropped = chatty message holding count 284 // elem = incoming message 285 // outgoing: if match != DIFFERENT 286 // delete chatty message holding count 287 // dropped = reference to last held-back incoming 288 // message, set to chatty count + 1 289 // currentLast = reference to elem 290 // break: if match == DIFFERENT 291 // log dropped (chatty message) 292 // dropped = nullptr -> State 0 293 // log reference to last held-back (currentLast) 294 // currentLast = copy of elem 295 // log elem 296 // 297 enum match_type match = identical(elem, currentLast); 298 if (match != DIFFERENT) { 299 if (dropped) { 300 // Sum up liblog tag messages? 301 if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) { 302 android_log_event_int_t* event = 303 reinterpret_cast<android_log_event_int_t*>( 304 const_cast<char*>(currentLast->getMsg())); 305 // 306 // To unit test, differentiate with something like: 307 // event->header.tag = htole32(CHATTY_LOG_TAG); 308 // here, then instead of delete currentLast below, 309 // log(currentLast) to see the incremental sums form. 310 // 311 uint32_t swab = event->payload.data; 312 unsigned long long total = htole32(swab); 313 event = reinterpret_cast<android_log_event_int_t*>( 314 const_cast<char*>(elem->getMsg())); 315 swab = event->payload.data; 316 317 lastLoggedElements[LOG_ID_EVENTS] = elem; 318 total += htole32(swab); 319 // check for overflow 320 if (total >= UINT32_MAX) { 321 log(currentLast); 322 pthread_mutex_unlock(&mLogElementsLock); 323 return len; 324 } 325 stats.add(currentLast); 326 stats.subtract(currentLast); 327 delete currentLast; 328 swab = total; 329 event->payload.data = htole32(swab); 330 pthread_mutex_unlock(&mLogElementsLock); 331 return len; 332 } 333 if (count == USHRT_MAX) { 334 log(dropped); 335 count = 1; 336 } else { 337 delete dropped; 338 ++count; 339 } 340 } 341 if (count) { 342 stats.add(currentLast); 343 stats.subtract(currentLast); 344 currentLast->setDropped(count); 345 } 346 droppedElements[log_id] = currentLast; 347 lastLoggedElements[log_id] = elem; 348 pthread_mutex_unlock(&mLogElementsLock); 349 return len; 350 } 351 if (dropped) { // State 1 or 2 352 if (count) { // State 2 353 log(dropped); // report chatty 354 } else { // State 1 355 delete dropped; 356 } 357 droppedElements[log_id] = nullptr; 358 log(currentLast); // report last message in the series 359 } else { // State 0 360 delete currentLast; 361 } 362 } 363 lastLoggedElements[log_id] = new LogBufferElement(*elem); 364 365 log(elem); 366 pthread_mutex_unlock(&mLogElementsLock); 367 368 return len; 369 } 370 371 // assumes mLogElementsLock held, owns elem, will look after garbage collection 372 void LogBuffer::log(LogBufferElement* elem) { 373 // cap on how far back we will sort in-place, otherwise append 374 static uint32_t too_far_back = 5; // five seconds 375 // Insert elements in time sorted order if possible 376 // NB: if end is region locked, place element at end of list 377 LogBufferElementCollection::iterator it = mLogElements.end(); 378 LogBufferElementCollection::iterator last = it; 379 if (__predict_true(it != mLogElements.begin())) --it; 380 if (__predict_false(it == mLogElements.begin()) || 381 __predict_true((*it)->getRealTime() <= elem->getRealTime()) || 382 __predict_false((((*it)->getRealTime().tv_sec - too_far_back) > 383 elem->getRealTime().tv_sec) && 384 (elem->getLogId() != LOG_ID_KERNEL) && 385 ((*it)->getLogId() != LOG_ID_KERNEL))) { 386 mLogElements.push_back(elem); 387 } else { 388 log_time end = log_time::EPOCH; 389 bool end_set = false; 390 bool end_always = false; 391 392 LogTimeEntry::lock(); 393 394 LastLogTimes::iterator times = mTimes.begin(); 395 while (times != mTimes.end()) { 396 LogTimeEntry* entry = (*times); 397 if (entry->owned_Locked()) { 398 if (!entry->mNonBlock) { 399 end_always = true; 400 break; 401 } 402 // it passing mEnd is blocked by the following checks. 403 if (!end_set || (end <= entry->mEnd)) { 404 end = entry->mEnd; 405 end_set = true; 406 } 407 } 408 times++; 409 } 410 411 if (end_always || (end_set && (end > (*it)->getRealTime()))) { 412 mLogElements.push_back(elem); 413 } else { 414 // should be short as timestamps are localized near end() 415 do { 416 last = it; 417 if (__predict_false(it == mLogElements.begin())) { 418 break; 419 } 420 --it; 421 } while (((*it)->getRealTime() > elem->getRealTime()) && 422 (!end_set || (end <= (*it)->getRealTime()))); 423 mLogElements.insert(last, elem); 424 } 425 LogTimeEntry::unlock(); 426 } 427 428 stats.add(elem); 429 maybePrune(elem->getLogId()); 430 } 431 432 // Prune at most 10% of the log entries or maxPrune, whichever is less. 433 // 434 // mLogElementsLock must be held when this function is called. 435 void LogBuffer::maybePrune(log_id_t id) { 436 size_t sizes = stats.sizes(id); 437 unsigned long maxSize = log_buffer_size(id); 438 if (sizes > maxSize) { 439 size_t sizeOver = sizes - ((maxSize * 9) / 10); 440 size_t elements = stats.realElements(id); 441 size_t minElements = elements / 100; 442 if (minElements < minPrune) { 443 minElements = minPrune; 444 } 445 unsigned long pruneRows = elements * sizeOver / sizes; 446 if (pruneRows < minElements) { 447 pruneRows = minElements; 448 } 449 if (pruneRows > maxPrune) { 450 pruneRows = maxPrune; 451 } 452 prune(id, pruneRows); 453 } 454 } 455 456 LogBufferElementCollection::iterator LogBuffer::erase( 457 LogBufferElementCollection::iterator it, bool coalesce) { 458 LogBufferElement* element = *it; 459 log_id_t id = element->getLogId(); 460 461 // Remove iterator references in the various lists that will become stale 462 // after the element is erased from the main logging list. 463 464 { // start of scope for found iterator 465 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) 466 ? element->getTag() 467 : element->getUid(); 468 LogBufferIteratorMap::iterator found = mLastWorst[id].find(key); 469 if ((found != mLastWorst[id].end()) && (it == found->second)) { 470 mLastWorst[id].erase(found); 471 } 472 } 473 474 { // start of scope for pid found iterator 475 // element->getUid() may not be AID_SYSTEM for next-best-watermark. 476 // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and 477 // long term code stability, find() check should be fast for those ids. 478 LogBufferPidIteratorMap::iterator found = 479 mLastWorstPidOfSystem[id].find(element->getPid()); 480 if ((found != mLastWorstPidOfSystem[id].end()) && 481 (it == found->second)) { 482 mLastWorstPidOfSystem[id].erase(found); 483 } 484 } 485 486 bool setLast[LOG_ID_MAX]; 487 bool doSetLast = false; 488 log_id_for_each(i) { 489 doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]); 490 } 491 #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES 492 LogBufferElementCollection::iterator bad = it; 493 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) 494 ? element->getTag() 495 : element->getUid(); 496 #endif 497 it = mLogElements.erase(it); 498 if (doSetLast) { 499 log_id_for_each(i) { 500 if (setLast[i]) { 501 if (__predict_false(it == mLogElements.end())) { // impossible 502 mLastSet[i] = false; 503 mLast[i] = mLogElements.begin(); 504 } else { 505 mLast[i] = it; // push down the road as next-best-watermark 506 } 507 } 508 } 509 } 510 #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES 511 log_id_for_each(i) { 512 for (auto b : mLastWorst[i]) { 513 if (bad == b.second) { 514 android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i, 515 b.first, key); 516 } 517 } 518 for (auto b : mLastWorstPidOfSystem[i]) { 519 if (bad == b.second) { 520 android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i, 521 b.first); 522 } 523 } 524 if (mLastSet[i] && (bad == mLast[i])) { 525 android::prdebug("stale mLast[%d]\n", i); 526 mLastSet[i] = false; 527 mLast[i] = mLogElements.begin(); 528 } 529 } 530 #endif 531 if (coalesce) { 532 stats.erase(element); 533 } else { 534 stats.subtract(element); 535 } 536 delete element; 537 538 return it; 539 } 540 541 // Define a temporary mechanism to report the last LogBufferElement pointer 542 // for the specified uid, pid and tid. Used below to help merge-sort when 543 // pruning for worst UID. 544 class LogBufferElementKey { 545 const union { 546 struct { 547 uint32_t uid; 548 uint16_t pid; 549 uint16_t tid; 550 } __packed; 551 uint64_t value; 552 } __packed; 553 554 public: 555 LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) 556 : uid(uid), pid(pid), tid(tid) { 557 } 558 explicit LogBufferElementKey(uint64_t key) : value(key) { 559 } 560 561 uint64_t getKey() { 562 return value; 563 } 564 }; 565 566 class LogBufferElementLast { 567 typedef std::unordered_map<uint64_t, LogBufferElement*> LogBufferElementMap; 568 LogBufferElementMap map; 569 570 public: 571 bool coalesce(LogBufferElement* element, unsigned short dropped) { 572 LogBufferElementKey key(element->getUid(), element->getPid(), 573 element->getTid()); 574 LogBufferElementMap::iterator it = map.find(key.getKey()); 575 if (it != map.end()) { 576 LogBufferElement* found = it->second; 577 unsigned short moreDropped = found->getDropped(); 578 if ((dropped + moreDropped) > USHRT_MAX) { 579 map.erase(it); 580 } else { 581 found->setDropped(dropped + moreDropped); 582 return true; 583 } 584 } 585 return false; 586 } 587 588 void add(LogBufferElement* element) { 589 LogBufferElementKey key(element->getUid(), element->getPid(), 590 element->getTid()); 591 map[key.getKey()] = element; 592 } 593 594 inline void clear() { 595 map.clear(); 596 } 597 598 void clear(LogBufferElement* element) { 599 log_time current = 600 element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0); 601 for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) { 602 LogBufferElement* mapElement = it->second; 603 if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) && 604 (current > mapElement->getRealTime())) { 605 it = map.erase(it); 606 } else { 607 ++it; 608 } 609 } 610 } 611 }; 612 613 // prune "pruneRows" of type "id" from the buffer. 614 // 615 // This garbage collection task is used to expire log entries. It is called to 616 // remove all logs (clear), all UID logs (unprivileged clear), or every 617 // 256 or 10% of the total logs (whichever is less) to prune the logs. 618 // 619 // First there is a prep phase where we discover the reader region lock that 620 // acts as a backstop to any pruning activity to stop there and go no further. 621 // 622 // There are three major pruning loops that follow. All expire from the oldest 623 // entries. Since there are multiple log buffers, the Android logging facility 624 // will appear to drop entries 'in the middle' when looking at multiple log 625 // sources and buffers. This effect is slightly more prominent when we prune 626 // the worst offender by logging source. Thus the logs slowly loose content 627 // and value as you move back in time. This is preferred since chatty sources 628 // invariably move the logs value down faster as less chatty sources would be 629 // expired in the noise. 630 // 631 // The first loop performs blacklisting and worst offender pruning. Falling 632 // through when there are no notable worst offenders and have not hit the 633 // region lock preventing further worst offender pruning. This loop also looks 634 // after managing the chatty log entries and merging to help provide 635 // statistical basis for blame. The chatty entries are not a notification of 636 // how much logs you may have, but instead represent how much logs you would 637 // have had in a virtual log buffer that is extended to cover all the in-memory 638 // logs without loss. They last much longer than the represented pruned logs 639 // since they get multiplied by the gains in the non-chatty log sources. 640 // 641 // The second loop get complicated because an algorithm of watermarks and 642 // history is maintained to reduce the order and keep processing time 643 // down to a minimum at scale. These algorithms can be costly in the face 644 // of larger log buffers, or severly limited processing time granted to a 645 // background task at lowest priority. 646 // 647 // This second loop does straight-up expiration from the end of the logs 648 // (again, remember for the specified log buffer id) but does some whitelist 649 // preservation. Thus whitelist is a Hail Mary low priority, blacklists and 650 // spam filtration all take priority. This second loop also checks if a region 651 // lock is causing us to buffer too much in the logs to help the reader(s), 652 // and will tell the slowest reader thread to skip log entries, and if 653 // persistent and hits a further threshold, kill the reader thread. 654 // 655 // The third thread is optional, and only gets hit if there was a whitelist 656 // and more needs to be pruned against the backstop of the region lock. 657 // 658 // mLogElementsLock must be held when this function is called. 659 // 660 bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { 661 LogTimeEntry* oldest = nullptr; 662 bool busy = false; 663 bool clearAll = pruneRows == ULONG_MAX; 664 665 LogTimeEntry::lock(); 666 667 // Region locked? 668 LastLogTimes::iterator times = mTimes.begin(); 669 while (times != mTimes.end()) { 670 LogTimeEntry* entry = (*times); 671 if (entry->owned_Locked() && entry->isWatching(id) && 672 (!oldest || (oldest->mStart > entry->mStart) || 673 ((oldest->mStart == entry->mStart) && 674 (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) { 675 oldest = entry; 676 } 677 times++; 678 } 679 log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max); 680 if (oldest) watermark = oldest->mStart - pruneMargin; 681 682 LogBufferElementCollection::iterator it; 683 684 if (__predict_false(caller_uid != AID_ROOT)) { // unlikely 685 // Only here if clear all request from non system source, so chatty 686 // filter logistics is not required. 687 it = mLastSet[id] ? mLast[id] : mLogElements.begin(); 688 while (it != mLogElements.end()) { 689 LogBufferElement* element = *it; 690 691 if ((element->getLogId() != id) || 692 (element->getUid() != caller_uid)) { 693 ++it; 694 continue; 695 } 696 697 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { 698 mLast[id] = it; 699 mLastSet[id] = true; 700 } 701 702 if (oldest && (watermark <= element->getRealTime())) { 703 busy = true; 704 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { 705 oldest->triggerReader_Locked(); 706 } else { 707 oldest->triggerSkip_Locked(id, pruneRows); 708 } 709 break; 710 } 711 712 it = erase(it); 713 if (--pruneRows == 0) { 714 break; 715 } 716 } 717 LogTimeEntry::unlock(); 718 return busy; 719 } 720 721 // prune by worst offenders; by blacklist, UID, and by PID of system UID 722 bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty(); 723 while (!clearAll && (pruneRows > 0)) { 724 // recalculate the worst offender on every batched pass 725 int worst = -1; // not valid for getUid() or getKey() 726 size_t worst_sizes = 0; 727 size_t second_worst_sizes = 0; 728 pid_t worstPid = 0; // POSIX guarantees PID != 0 729 730 if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) { 731 // Calculate threshold as 12.5% of available storage 732 size_t threshold = log_buffer_size(id) / 8; 733 734 if ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) { 735 stats.sortTags(AID_ROOT, (pid_t)0, 2, id) 736 .findWorst(worst, worst_sizes, second_worst_sizes, 737 threshold); 738 // per-pid filter for AID_SYSTEM sources is too complex 739 } else { 740 stats.sort(AID_ROOT, (pid_t)0, 2, id) 741 .findWorst(worst, worst_sizes, second_worst_sizes, 742 threshold); 743 744 if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) { 745 stats.sortPids(worst, (pid_t)0, 2, id) 746 .findWorst(worstPid, worst_sizes, second_worst_sizes); 747 } 748 } 749 } 750 751 // skip if we have neither worst nor naughty filters 752 if ((worst == -1) && !hasBlacklist) { 753 break; 754 } 755 756 bool kick = false; 757 bool leading = true; 758 it = mLastSet[id] ? mLast[id] : mLogElements.begin(); 759 // Perform at least one mandatory garbage collection cycle in following 760 // - clear leading chatty tags 761 // - coalesce chatty tags 762 // - check age-out of preserved logs 763 bool gc = pruneRows <= 1; 764 if (!gc && (worst != -1)) { 765 { // begin scope for worst found iterator 766 LogBufferIteratorMap::iterator found = 767 mLastWorst[id].find(worst); 768 if ((found != mLastWorst[id].end()) && 769 (found->second != mLogElements.end())) { 770 leading = false; 771 it = found->second; 772 } 773 } 774 if (worstPid) { // begin scope for pid worst found iterator 775 // FYI: worstPid only set if !LOG_ID_EVENTS and 776 // !LOG_ID_SECURITY, not going to make that assumption ... 777 LogBufferPidIteratorMap::iterator found = 778 mLastWorstPidOfSystem[id].find(worstPid); 779 if ((found != mLastWorstPidOfSystem[id].end()) && 780 (found->second != mLogElements.end())) { 781 leading = false; 782 it = found->second; 783 } 784 } 785 } 786 static const timespec too_old = { EXPIRE_HOUR_THRESHOLD * 60 * 60, 0 }; 787 LogBufferElementCollection::iterator lastt; 788 lastt = mLogElements.end(); 789 --lastt; 790 LogBufferElementLast last; 791 while (it != mLogElements.end()) { 792 LogBufferElement* element = *it; 793 794 if (oldest && (watermark <= element->getRealTime())) { 795 busy = true; 796 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { 797 oldest->triggerReader_Locked(); 798 } 799 break; 800 } 801 802 if (element->getLogId() != id) { 803 ++it; 804 continue; 805 } 806 // below this point element->getLogId() == id 807 808 if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) { 809 mLast[id] = it; 810 mLastSet[id] = true; 811 } 812 813 unsigned short dropped = element->getDropped(); 814 815 // remove any leading drops 816 if (leading && dropped) { 817 it = erase(it); 818 continue; 819 } 820 821 if (dropped && last.coalesce(element, dropped)) { 822 it = erase(it, true); 823 continue; 824 } 825 826 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) 827 ? element->getTag() 828 : element->getUid(); 829 830 if (hasBlacklist && mPrune.naughty(element)) { 831 last.clear(element); 832 it = erase(it); 833 if (dropped) { 834 continue; 835 } 836 837 pruneRows--; 838 if (pruneRows == 0) { 839 break; 840 } 841 842 if (key == worst) { 843 kick = true; 844 if (worst_sizes < second_worst_sizes) { 845 break; 846 } 847 worst_sizes -= element->getMsgLen(); 848 } 849 continue; 850 } 851 852 if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old)) || 853 (element->getRealTime() > (*lastt)->getRealTime())) { 854 break; 855 } 856 857 if (dropped) { 858 last.add(element); 859 if (worstPid && 860 ((!gc && (element->getPid() == worstPid)) || 861 (mLastWorstPidOfSystem[id].find(element->getPid()) == 862 mLastWorstPidOfSystem[id].end()))) { 863 // element->getUid() may not be AID_SYSTEM, next best 864 // watermark if current one empty. id is not LOG_ID_EVENTS 865 // or LOG_ID_SECURITY because of worstPid check. 866 mLastWorstPidOfSystem[id][element->getPid()] = it; 867 } 868 if ((!gc && !worstPid && (key == worst)) || 869 (mLastWorst[id].find(key) == mLastWorst[id].end())) { 870 mLastWorst[id][key] = it; 871 } 872 ++it; 873 continue; 874 } 875 876 if ((key != worst) || 877 (worstPid && (element->getPid() != worstPid))) { 878 leading = false; 879 last.clear(element); 880 ++it; 881 continue; 882 } 883 // key == worst below here 884 // If worstPid set, then element->getPid() == worstPid below here 885 886 pruneRows--; 887 if (pruneRows == 0) { 888 break; 889 } 890 891 kick = true; 892 893 unsigned short len = element->getMsgLen(); 894 895 // do not create any leading drops 896 if (leading) { 897 it = erase(it); 898 } else { 899 stats.drop(element); 900 element->setDropped(1); 901 if (last.coalesce(element, 1)) { 902 it = erase(it, true); 903 } else { 904 last.add(element); 905 if (worstPid && 906 (!gc || (mLastWorstPidOfSystem[id].find(worstPid) == 907 mLastWorstPidOfSystem[id].end()))) { 908 // element->getUid() may not be AID_SYSTEM, next best 909 // watermark if current one empty. id is not 910 // LOG_ID_EVENTS or LOG_ID_SECURITY because of worstPid. 911 mLastWorstPidOfSystem[id][worstPid] = it; 912 } 913 if ((!gc && !worstPid) || 914 (mLastWorst[id].find(worst) == mLastWorst[id].end())) { 915 mLastWorst[id][worst] = it; 916 } 917 ++it; 918 } 919 } 920 if (worst_sizes < second_worst_sizes) { 921 break; 922 } 923 worst_sizes -= len; 924 } 925 last.clear(); 926 927 if (!kick || !mPrune.worstUidEnabled()) { 928 break; // the following loop will ask bad clients to skip/drop 929 } 930 } 931 932 bool whitelist = false; 933 bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll; 934 it = mLastSet[id] ? mLast[id] : mLogElements.begin(); 935 while ((pruneRows > 0) && (it != mLogElements.end())) { 936 LogBufferElement* element = *it; 937 938 if (element->getLogId() != id) { 939 it++; 940 continue; 941 } 942 943 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { 944 mLast[id] = it; 945 mLastSet[id] = true; 946 } 947 948 if (oldest && (watermark <= element->getRealTime())) { 949 busy = true; 950 if (whitelist) { 951 break; 952 } 953 954 if (stats.sizes(id) > (2 * log_buffer_size(id))) { 955 // kick a misbehaving log reader client off the island 956 oldest->release_Locked(); 957 } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { 958 oldest->triggerReader_Locked(); 959 } else { 960 oldest->triggerSkip_Locked(id, pruneRows); 961 } 962 break; 963 } 964 965 if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) { 966 // WhiteListed 967 whitelist = true; 968 it++; 969 continue; 970 } 971 972 it = erase(it); 973 pruneRows--; 974 } 975 976 // Do not save the whitelist if we are reader range limited 977 if (whitelist && (pruneRows > 0)) { 978 it = mLastSet[id] ? mLast[id] : mLogElements.begin(); 979 while ((it != mLogElements.end()) && (pruneRows > 0)) { 980 LogBufferElement* element = *it; 981 982 if (element->getLogId() != id) { 983 ++it; 984 continue; 985 } 986 987 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { 988 mLast[id] = it; 989 mLastSet[id] = true; 990 } 991 992 if (oldest && (watermark <= element->getRealTime())) { 993 busy = true; 994 if (stats.sizes(id) > (2 * log_buffer_size(id))) { 995 // kick a misbehaving log reader client off the island 996 oldest->release_Locked(); 997 } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { 998 oldest->triggerReader_Locked(); 999 } else { 1000 oldest->triggerSkip_Locked(id, pruneRows); 1001 } 1002 break; 1003 } 1004 1005 it = erase(it); 1006 pruneRows--; 1007 } 1008 } 1009 1010 LogTimeEntry::unlock(); 1011 1012 return (pruneRows > 0) && busy; 1013 } 1014 1015 // clear all rows of type "id" from the buffer. 1016 bool LogBuffer::clear(log_id_t id, uid_t uid) { 1017 bool busy = true; 1018 // If it takes more than 4 tries (seconds) to clear, then kill reader(s) 1019 for (int retry = 4;;) { 1020 if (retry == 1) { // last pass 1021 // Check if it is still busy after the sleep, we say prune 1022 // one entry, not another clear run, so we are looking for 1023 // the quick side effect of the return value to tell us if 1024 // we have a _blocked_ reader. 1025 pthread_mutex_lock(&mLogElementsLock); 1026 busy = prune(id, 1, uid); 1027 pthread_mutex_unlock(&mLogElementsLock); 1028 // It is still busy, blocked reader(s), lets kill them all! 1029 // otherwise, lets be a good citizen and preserve the slow 1030 // readers and let the clear run (below) deal with determining 1031 // if we are still blocked and return an error code to caller. 1032 if (busy) { 1033 LogTimeEntry::lock(); 1034 LastLogTimes::iterator times = mTimes.begin(); 1035 while (times != mTimes.end()) { 1036 LogTimeEntry* entry = (*times); 1037 // Killer punch 1038 if (entry->owned_Locked() && entry->isWatching(id)) { 1039 entry->release_Locked(); 1040 } 1041 times++; 1042 } 1043 LogTimeEntry::unlock(); 1044 } 1045 } 1046 pthread_mutex_lock(&mLogElementsLock); 1047 busy = prune(id, ULONG_MAX, uid); 1048 pthread_mutex_unlock(&mLogElementsLock); 1049 if (!busy || !--retry) { 1050 break; 1051 } 1052 sleep(1); // Let reader(s) catch up after notification 1053 } 1054 return busy; 1055 } 1056 1057 // get the used space associated with "id". 1058 unsigned long LogBuffer::getSizeUsed(log_id_t id) { 1059 pthread_mutex_lock(&mLogElementsLock); 1060 size_t retval = stats.sizes(id); 1061 pthread_mutex_unlock(&mLogElementsLock); 1062 return retval; 1063 } 1064 1065 // set the total space allocated to "id" 1066 int LogBuffer::setSize(log_id_t id, unsigned long size) { 1067 // Reasonable limits ... 1068 if (!__android_logger_valid_buffer_size(size)) { 1069 return -1; 1070 } 1071 pthread_mutex_lock(&mLogElementsLock); 1072 log_buffer_size(id) = size; 1073 pthread_mutex_unlock(&mLogElementsLock); 1074 return 0; 1075 } 1076 1077 // get the total space allocated to "id" 1078 unsigned long LogBuffer::getSize(log_id_t id) { 1079 pthread_mutex_lock(&mLogElementsLock); 1080 size_t retval = log_buffer_size(id); 1081 pthread_mutex_unlock(&mLogElementsLock); 1082 return retval; 1083 } 1084 1085 log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, 1086 pid_t* lastTid, bool privileged, bool security, 1087 int (*filter)(const LogBufferElement* element, 1088 void* arg), 1089 void* arg) { 1090 LogBufferElementCollection::iterator it; 1091 uid_t uid = reader->getUid(); 1092 1093 pthread_mutex_lock(&mLogElementsLock); 1094 1095 if (start == log_time::EPOCH) { 1096 // client wants to start from the beginning 1097 it = mLogElements.begin(); 1098 } else { 1099 // 3 second limit to continue search for out-of-order entries. 1100 log_time min = start - pruneMargin; 1101 1102 // Cap to 300 iterations we look back for out-of-order entries. 1103 size_t count = 300; 1104 1105 // Client wants to start from some specified time. Chances are 1106 // we are better off starting from the end of the time sorted list. 1107 LogBufferElementCollection::iterator last; 1108 for (last = it = mLogElements.end(); it != mLogElements.begin(); 1109 /* do nothing */) { 1110 --it; 1111 LogBufferElement* element = *it; 1112 if (element->getRealTime() > start) { 1113 last = it; 1114 } else if (!--count || (element->getRealTime() < min)) { 1115 break; 1116 } 1117 } 1118 it = last; 1119 } 1120 1121 log_time max = start; 1122 1123 LogBufferElement* lastElement = nullptr; // iterator corruption paranoia 1124 static const size_t maxSkip = 4194304; // maximum entries to skip 1125 size_t skip = maxSkip; 1126 for (; it != mLogElements.end(); ++it) { 1127 LogBufferElement* element = *it; 1128 1129 if (!--skip) { 1130 android::prdebug("reader.per: too many elements skipped"); 1131 break; 1132 } 1133 if (element == lastElement) { 1134 android::prdebug("reader.per: identical elements"); 1135 break; 1136 } 1137 lastElement = element; 1138 1139 if (!privileged && (element->getUid() != uid)) { 1140 continue; 1141 } 1142 1143 if (!security && (element->getLogId() == LOG_ID_SECURITY)) { 1144 continue; 1145 } 1146 1147 if (element->getRealTime() <= start) { 1148 continue; 1149 } 1150 1151 // NB: calling out to another object with mLogElementsLock held (safe) 1152 if (filter) { 1153 int ret = (*filter)(element, arg); 1154 if (ret == false) { 1155 continue; 1156 } 1157 if (ret != true) { 1158 break; 1159 } 1160 } 1161 1162 bool sameTid = false; 1163 if (lastTid) { 1164 sameTid = lastTid[element->getLogId()] == element->getTid(); 1165 // Dropped (chatty) immediately following a valid log from the 1166 // same source in the same log buffer indicates we have a 1167 // multiple identical squash. chatty that differs source 1168 // is due to spam filter. chatty to chatty of different 1169 // source is also due to spam filter. 1170 lastTid[element->getLogId()] = 1171 (element->getDropped() && !sameTid) ? 0 : element->getTid(); 1172 } 1173 1174 pthread_mutex_unlock(&mLogElementsLock); 1175 1176 // range locking in LastLogTimes looks after us 1177 max = element->flushTo(reader, this, privileged, sameTid); 1178 1179 if (max == element->FLUSH_ERROR) { 1180 return max; 1181 } 1182 1183 skip = maxSkip; 1184 pthread_mutex_lock(&mLogElementsLock); 1185 } 1186 pthread_mutex_unlock(&mLogElementsLock); 1187 1188 return max; 1189 } 1190 1191 std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid, 1192 unsigned int logMask) { 1193 pthread_mutex_lock(&mLogElementsLock); 1194 1195 std::string ret = stats.format(uid, pid, logMask); 1196 1197 pthread_mutex_unlock(&mLogElementsLock); 1198 1199 return ret; 1200 } 1201
