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