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 "LogKlog.h"
32 #include "LogReader.h"
33
34 // Default
35 #define LOG_BUFFER_SIZE (256 * 1024) // Tuned with ro.logd.size per-platform
36 #define log_buffer_size(id) mMaxSize[id]
37 #define LOG_BUFFER_MIN_SIZE (64 * 1024UL)
38 #define LOG_BUFFER_MAX_SIZE (256 * 1024 * 1024UL)
39
valid_size(unsigned long value)40 static bool valid_size(unsigned long value) {
41 if ((value < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < value)) {
42 return false;
43 }
44
45 long pages = sysconf(_SC_PHYS_PAGES);
46 if (pages < 1) {
47 return true;
48 }
49
50 long pagesize = sysconf(_SC_PAGESIZE);
51 if (pagesize <= 1) {
52 pagesize = PAGE_SIZE;
53 }
54
55 // maximum memory impact a somewhat arbitrary ~3%
56 pages = (pages + 31) / 32;
57 unsigned long maximum = pages * pagesize;
58
59 if ((maximum < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < maximum)) {
60 return true;
61 }
62
63 return value <= maximum;
64 }
65
property_get_size(const char * key)66 static unsigned long property_get_size(const char *key) {
67 char property[PROPERTY_VALUE_MAX];
68 property_get(key, property, "");
69
70 char *cp;
71 unsigned long value = strtoul(property, &cp, 10);
72
73 switch(*cp) {
74 case 'm':
75 case 'M':
76 value *= 1024;
77 /* FALLTHRU */
78 case 'k':
79 case 'K':
80 value *= 1024;
81 /* FALLTHRU */
82 case '\0':
83 break;
84
85 default:
86 value = 0;
87 }
88
89 if (!valid_size(value)) {
90 value = 0;
91 }
92
93 return value;
94 }
95
init()96 void LogBuffer::init() {
97 static const char global_tuneable[] = "persist.logd.size"; // Settings App
98 static const char global_default[] = "ro.logd.size"; // BoardConfig.mk
99
100 unsigned long default_size = property_get_size(global_tuneable);
101 if (!default_size) {
102 default_size = property_get_size(global_default);
103 if (!default_size) {
104 default_size = property_get_bool("ro.config.low_ram",
105 BOOL_DEFAULT_FALSE)
106 ? LOG_BUFFER_MIN_SIZE // 64K
107 : LOG_BUFFER_SIZE; // 256K
108 }
109 }
110
111 log_id_for_each(i) {
112 mLastSet[i] = false;
113 mLast[i] = mLogElements.begin();
114
115 char key[PROP_NAME_MAX];
116
117 snprintf(key, sizeof(key), "%s.%s",
118 global_tuneable, android_log_id_to_name(i));
119 unsigned long property_size = property_get_size(key);
120
121 if (!property_size) {
122 snprintf(key, sizeof(key), "%s.%s",
123 global_default, android_log_id_to_name(i));
124 property_size = property_get_size(key);
125 }
126
127 if (!property_size) {
128 property_size = default_size;
129 }
130
131 if (!property_size) {
132 property_size = LOG_BUFFER_SIZE;
133 }
134
135 if (setSize(i, property_size)) {
136 setSize(i, LOG_BUFFER_MIN_SIZE);
137 }
138 }
139 bool lastMonotonic = monotonic;
140 monotonic = android_log_clockid() == CLOCK_MONOTONIC;
141 if (lastMonotonic != monotonic) {
142 //
143 // Fixup all timestamps, may not be 100% accurate, but better than
144 // throwing what we have away when we get 'surprised' by a change.
145 // In-place element fixup so no need to check reader-lock. Entries
146 // should already be in timestamp order, but we could end up with a
147 // few out-of-order entries if new monotonics come in before we
148 // are notified of the reinit change in status. A Typical example would
149 // be:
150 // --------- beginning of system
151 // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
152 // --------- beginning of kernel
153 // 0.000000 0 0 I : Initializing cgroup subsys
154 // as the act of mounting /data would trigger persist.logd.timestamp to
155 // be corrected. 1/30 corner case YMMV.
156 //
157 pthread_mutex_lock(&mLogElementsLock);
158 LogBufferElementCollection::iterator it = mLogElements.begin();
159 while((it != mLogElements.end())) {
160 LogBufferElement *e = *it;
161 if (monotonic) {
162 if (!android::isMonotonic(e->mRealTime)) {
163 LogKlog::convertRealToMonotonic(e->mRealTime);
164 }
165 } else {
166 if (android::isMonotonic(e->mRealTime)) {
167 LogKlog::convertMonotonicToReal(e->mRealTime);
168 }
169 }
170 ++it;
171 }
172 pthread_mutex_unlock(&mLogElementsLock);
173 }
174
175 // We may have been triggered by a SIGHUP. Release any sleeping reader
176 // threads to dump their current content.
177 //
178 // NB: this is _not_ performed in the context of a SIGHUP, it is
179 // performed during startup, and in context of reinit administrative thread
180 LogTimeEntry::lock();
181
182 LastLogTimes::iterator times = mTimes.begin();
183 while(times != mTimes.end()) {
184 LogTimeEntry *entry = (*times);
185 if (entry->owned_Locked()) {
186 entry->triggerReader_Locked();
187 }
188 times++;
189 }
190
191 LogTimeEntry::unlock();
192 }
193
LogBuffer(LastLogTimes * times)194 LogBuffer::LogBuffer(LastLogTimes *times):
195 monotonic(android_log_clockid() == CLOCK_MONOTONIC),
196 mTimes(*times) {
197 pthread_mutex_init(&mLogElementsLock, NULL);
198
199 init();
200 }
201
log(log_id_t log_id,log_time realtime,uid_t uid,pid_t pid,pid_t tid,const char * msg,unsigned short len)202 int LogBuffer::log(log_id_t log_id, log_time realtime,
203 uid_t uid, pid_t pid, pid_t tid,
204 const char *msg, unsigned short len) {
205 if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
206 return -EINVAL;
207 }
208
209 LogBufferElement *elem = new LogBufferElement(log_id, realtime,
210 uid, pid, tid, msg, len);
211 if (log_id != LOG_ID_SECURITY) {
212 int prio = ANDROID_LOG_INFO;
213 const char *tag = NULL;
214 if (log_id == LOG_ID_EVENTS) {
215 tag = android::tagToName(elem->getTag());
216 } else {
217 prio = *msg;
218 tag = msg + 1;
219 }
220 if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) {
221 // Log traffic received to total
222 pthread_mutex_lock(&mLogElementsLock);
223 stats.add(elem);
224 stats.subtract(elem);
225 pthread_mutex_unlock(&mLogElementsLock);
226 delete elem;
227 return -EACCES;
228 }
229 }
230
231 pthread_mutex_lock(&mLogElementsLock);
232
233 // Insert elements in time sorted order if possible
234 // NB: if end is region locked, place element at end of list
235 LogBufferElementCollection::iterator it = mLogElements.end();
236 LogBufferElementCollection::iterator last = it;
237 while (last != mLogElements.begin()) {
238 --it;
239 if ((*it)->getRealTime() <= realtime) {
240 break;
241 }
242 last = it;
243 }
244
245 if (last == mLogElements.end()) {
246 mLogElements.push_back(elem);
247 } else {
248 uint64_t end = 1;
249 bool end_set = false;
250 bool end_always = false;
251
252 LogTimeEntry::lock();
253
254 LastLogTimes::iterator times = mTimes.begin();
255 while(times != mTimes.end()) {
256 LogTimeEntry *entry = (*times);
257 if (entry->owned_Locked()) {
258 if (!entry->mNonBlock) {
259 end_always = true;
260 break;
261 }
262 if (!end_set || (end <= entry->mEnd)) {
263 end = entry->mEnd;
264 end_set = true;
265 }
266 }
267 times++;
268 }
269
270 if (end_always
271 || (end_set && (end >= (*last)->getSequence()))) {
272 mLogElements.push_back(elem);
273 } else {
274 mLogElements.insert(last,elem);
275 }
276
277 LogTimeEntry::unlock();
278 }
279
280 stats.add(elem);
281 maybePrune(log_id);
282 pthread_mutex_unlock(&mLogElementsLock);
283
284 return len;
285 }
286
287 // Prune at most 10% of the log entries or maxPrune, whichever is less.
288 //
289 // mLogElementsLock must be held when this function is called.
maybePrune(log_id_t id)290 void LogBuffer::maybePrune(log_id_t id) {
291 size_t sizes = stats.sizes(id);
292 unsigned long maxSize = log_buffer_size(id);
293 if (sizes > maxSize) {
294 size_t sizeOver = sizes - ((maxSize * 9) / 10);
295 size_t elements = stats.realElements(id);
296 size_t minElements = elements / 100;
297 if (minElements < minPrune) {
298 minElements = minPrune;
299 }
300 unsigned long pruneRows = elements * sizeOver / sizes;
301 if (pruneRows < minElements) {
302 pruneRows = minElements;
303 }
304 if (pruneRows > maxPrune) {
305 pruneRows = maxPrune;
306 }
307 prune(id, pruneRows);
308 }
309 }
310
erase(LogBufferElementCollection::iterator it,bool coalesce)311 LogBufferElementCollection::iterator LogBuffer::erase(
312 LogBufferElementCollection::iterator it, bool coalesce) {
313 LogBufferElement *element = *it;
314 log_id_t id = element->getLogId();
315
316 { // start of scope for uid found iterator
317 LogBufferIteratorMap::iterator found =
318 mLastWorstUid[id].find(element->getUid());
319 if ((found != mLastWorstUid[id].end())
320 && (it == found->second)) {
321 mLastWorstUid[id].erase(found);
322 }
323 }
324
325 if (element->getUid() == AID_SYSTEM) {
326 // start of scope for pid found iterator
327 LogBufferPidIteratorMap::iterator found =
328 mLastWorstPidOfSystem[id].find(element->getPid());
329 if ((found != mLastWorstPidOfSystem[id].end())
330 && (it == found->second)) {
331 mLastWorstPidOfSystem[id].erase(found);
332 }
333 }
334
335 bool setLast[LOG_ID_MAX];
336 bool doSetLast = false;
337 log_id_for_each(i) {
338 doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]);
339 }
340 it = mLogElements.erase(it);
341 if (doSetLast) {
342 log_id_for_each(i) {
343 if (setLast[i]) {
344 if (it == mLogElements.end()) { // unlikely
345 mLastSet[i] = false;
346 } else {
347 mLast[i] = it;
348 }
349 }
350 }
351 }
352 if (coalesce) {
353 stats.erase(element);
354 } else {
355 stats.subtract(element);
356 }
357 delete element;
358
359 return it;
360 }
361
362 // Define a temporary mechanism to report the last LogBufferElement pointer
363 // for the specified uid, pid and tid. Used below to help merge-sort when
364 // pruning for worst UID.
365 class LogBufferElementKey {
366 const union {
367 struct {
368 uint16_t uid;
369 uint16_t pid;
370 uint16_t tid;
371 uint16_t padding;
372 } __packed;
373 uint64_t value;
374 } __packed;
375
376 public:
LogBufferElementKey(uid_t uid,pid_t pid,pid_t tid)377 LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid):
378 uid(uid),
379 pid(pid),
380 tid(tid),
381 padding(0) {
382 }
LogBufferElementKey(uint64_t key)383 LogBufferElementKey(uint64_t key):value(key) { }
384
getKey()385 uint64_t getKey() { return value; }
386 };
387
388 class LogBufferElementLast {
389
390 typedef std::unordered_map<uint64_t, LogBufferElement *> LogBufferElementMap;
391 LogBufferElementMap map;
392
393 public:
394
coalesce(LogBufferElement * element,unsigned short dropped)395 bool coalesce(LogBufferElement *element, unsigned short dropped) {
396 LogBufferElementKey key(element->getUid(),
397 element->getPid(),
398 element->getTid());
399 LogBufferElementMap::iterator it = map.find(key.getKey());
400 if (it != map.end()) {
401 LogBufferElement *found = it->second;
402 unsigned short moreDropped = found->getDropped();
403 if ((dropped + moreDropped) > USHRT_MAX) {
404 map.erase(it);
405 } else {
406 found->setDropped(dropped + moreDropped);
407 return true;
408 }
409 }
410 return false;
411 }
412
add(LogBufferElement * element)413 void add(LogBufferElement *element) {
414 LogBufferElementKey key(element->getUid(),
415 element->getPid(),
416 element->getTid());
417 map[key.getKey()] = element;
418 }
419
clear()420 inline void clear() {
421 map.clear();
422 }
423
clear(LogBufferElement * element)424 void clear(LogBufferElement *element) {
425 uint64_t current = element->getRealTime().nsec()
426 - (EXPIRE_RATELIMIT * NS_PER_SEC);
427 for(LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
428 LogBufferElement *mapElement = it->second;
429 if ((mapElement->getDropped() >= EXPIRE_THRESHOLD)
430 && (current > mapElement->getRealTime().nsec())) {
431 it = map.erase(it);
432 } else {
433 ++it;
434 }
435 }
436 }
437
438 };
439
440 // prune "pruneRows" of type "id" from the buffer.
441 //
442 // This garbage collection task is used to expire log entries. It is called to
443 // remove all logs (clear), all UID logs (unprivileged clear), or every
444 // 256 or 10% of the total logs (whichever is less) to prune the logs.
445 //
446 // First there is a prep phase where we discover the reader region lock that
447 // acts as a backstop to any pruning activity to stop there and go no further.
448 //
449 // There are three major pruning loops that follow. All expire from the oldest
450 // entries. Since there are multiple log buffers, the Android logging facility
451 // will appear to drop entries 'in the middle' when looking at multiple log
452 // sources and buffers. This effect is slightly more prominent when we prune
453 // the worst offender by logging source. Thus the logs slowly loose content
454 // and value as you move back in time. This is preferred since chatty sources
455 // invariably move the logs value down faster as less chatty sources would be
456 // expired in the noise.
457 //
458 // The first loop performs blacklisting and worst offender pruning. Falling
459 // through when there are no notable worst offenders and have not hit the
460 // region lock preventing further worst offender pruning. This loop also looks
461 // after managing the chatty log entries and merging to help provide
462 // statistical basis for blame. The chatty entries are not a notification of
463 // how much logs you may have, but instead represent how much logs you would
464 // have had in a virtual log buffer that is extended to cover all the in-memory
465 // logs without loss. They last much longer than the represented pruned logs
466 // since they get multiplied by the gains in the non-chatty log sources.
467 //
468 // The second loop get complicated because an algorithm of watermarks and
469 // history is maintained to reduce the order and keep processing time
470 // down to a minimum at scale. These algorithms can be costly in the face
471 // of larger log buffers, or severly limited processing time granted to a
472 // background task at lowest priority.
473 //
474 // This second loop does straight-up expiration from the end of the logs
475 // (again, remember for the specified log buffer id) but does some whitelist
476 // preservation. Thus whitelist is a Hail Mary low priority, blacklists and
477 // spam filtration all take priority. This second loop also checks if a region
478 // lock is causing us to buffer too much in the logs to help the reader(s),
479 // and will tell the slowest reader thread to skip log entries, and if
480 // persistent and hits a further threshold, kill the reader thread.
481 //
482 // The third thread is optional, and only gets hit if there was a whitelist
483 // and more needs to be pruned against the backstop of the region lock.
484 //
485 // mLogElementsLock must be held when this function is called.
486 //
prune(log_id_t id,unsigned long pruneRows,uid_t caller_uid)487 bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
488 LogTimeEntry *oldest = NULL;
489 bool busy = false;
490 bool clearAll = pruneRows == ULONG_MAX;
491
492 LogTimeEntry::lock();
493
494 // Region locked?
495 LastLogTimes::iterator times = mTimes.begin();
496 while(times != mTimes.end()) {
497 LogTimeEntry *entry = (*times);
498 if (entry->owned_Locked() && entry->isWatching(id)
499 && (!oldest ||
500 (oldest->mStart > entry->mStart) ||
501 ((oldest->mStart == entry->mStart) &&
502 (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
503 oldest = entry;
504 }
505 times++;
506 }
507
508 LogBufferElementCollection::iterator it;
509
510 if (caller_uid != AID_ROOT) {
511 // Only here if clearAll condition (pruneRows == ULONG_MAX)
512 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
513 while (it != mLogElements.end()) {
514 LogBufferElement *element = *it;
515
516 if ((element->getLogId() != id) || (element->getUid() != caller_uid)) {
517 ++it;
518 continue;
519 }
520
521 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
522 mLast[id] = it;
523 mLastSet[id] = true;
524 }
525
526 if (oldest && (oldest->mStart <= element->getSequence())) {
527 busy = true;
528 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
529 oldest->triggerReader_Locked();
530 } else {
531 oldest->triggerSkip_Locked(id, pruneRows);
532 }
533 break;
534 }
535
536 it = erase(it);
537 pruneRows--;
538 }
539 LogTimeEntry::unlock();
540 return busy;
541 }
542
543 // prune by worst offenders; by blacklist, UID, and by PID of system UID
544 bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty();
545 while (!clearAll && (pruneRows > 0)) {
546 // recalculate the worst offender on every batched pass
547 uid_t worst = (uid_t) -1;
548 size_t worst_sizes = 0;
549 size_t second_worst_sizes = 0;
550 pid_t worstPid = 0; // POSIX guarantees PID != 0
551
552 if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) {
553 { // begin scope for UID sorted list
554 std::unique_ptr<const UidEntry *[]> sorted = stats.sort(
555 AID_ROOT, (pid_t)0, 2, id);
556
557 if (sorted.get() && sorted[0] && sorted[1]) {
558 worst_sizes = sorted[0]->getSizes();
559 // Calculate threshold as 12.5% of available storage
560 size_t threshold = log_buffer_size(id) / 8;
561 if ((worst_sizes > threshold)
562 // Allow time horizon to extend roughly tenfold, assume
563 // average entry length is 100 characters.
564 && (worst_sizes > (10 * sorted[0]->getDropped()))) {
565 worst = sorted[0]->getKey();
566 second_worst_sizes = sorted[1]->getSizes();
567 if (second_worst_sizes < threshold) {
568 second_worst_sizes = threshold;
569 }
570 }
571 }
572 }
573
574 if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) {
575 // begin scope of PID sorted list
576 std::unique_ptr<const PidEntry *[]> sorted = stats.sort(
577 worst, (pid_t)0, 2, id, worst);
578 if (sorted.get() && sorted[0] && sorted[1]) {
579 worstPid = sorted[0]->getKey();
580 second_worst_sizes = worst_sizes
581 - sorted[0]->getSizes()
582 + sorted[1]->getSizes();
583 }
584 }
585 }
586
587 // skip if we have neither worst nor naughty filters
588 if ((worst == (uid_t) -1) && !hasBlacklist) {
589 break;
590 }
591
592 bool kick = false;
593 bool leading = true;
594 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
595 // Perform at least one mandatory garbage collection cycle in following
596 // - clear leading chatty tags
597 // - coalesce chatty tags
598 // - check age-out of preserved logs
599 bool gc = pruneRows <= 1;
600 if (!gc && (worst != (uid_t) -1)) {
601 { // begin scope for uid worst found iterator
602 LogBufferIteratorMap::iterator found = mLastWorstUid[id].find(worst);
603 if ((found != mLastWorstUid[id].end())
604 && (found->second != mLogElements.end())) {
605 leading = false;
606 it = found->second;
607 }
608 }
609 if (worstPid) {
610 // begin scope for pid worst found iterator
611 LogBufferPidIteratorMap::iterator found
612 = mLastWorstPidOfSystem[id].find(worstPid);
613 if ((found != mLastWorstPidOfSystem[id].end())
614 && (found->second != mLogElements.end())) {
615 leading = false;
616 it = found->second;
617 }
618 }
619 }
620 static const timespec too_old = {
621 EXPIRE_HOUR_THRESHOLD * 60 * 60, 0
622 };
623 LogBufferElementCollection::iterator lastt;
624 lastt = mLogElements.end();
625 --lastt;
626 LogBufferElementLast last;
627 while (it != mLogElements.end()) {
628 LogBufferElement *element = *it;
629
630 if (oldest && (oldest->mStart <= element->getSequence())) {
631 busy = true;
632 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
633 oldest->triggerReader_Locked();
634 }
635 break;
636 }
637
638 if (element->getLogId() != id) {
639 ++it;
640 continue;
641 }
642
643 if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) {
644 mLast[id] = it;
645 mLastSet[id] = true;
646 }
647
648 unsigned short dropped = element->getDropped();
649
650 // remove any leading drops
651 if (leading && dropped) {
652 it = erase(it);
653 continue;
654 }
655
656 if (dropped && last.coalesce(element, dropped)) {
657 it = erase(it, true);
658 continue;
659 }
660
661 if (hasBlacklist && mPrune.naughty(element)) {
662 last.clear(element);
663 it = erase(it);
664 if (dropped) {
665 continue;
666 }
667
668 pruneRows--;
669 if (pruneRows == 0) {
670 break;
671 }
672
673 if (element->getUid() == worst) {
674 kick = true;
675 if (worst_sizes < second_worst_sizes) {
676 break;
677 }
678 worst_sizes -= element->getMsgLen();
679 }
680 continue;
681 }
682
683 if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old))
684 || (element->getRealTime() > (*lastt)->getRealTime())) {
685 break;
686 }
687
688 if (dropped) {
689 last.add(element);
690 if (worstPid
691 && ((!gc && (element->getPid() == worstPid))
692 || (mLastWorstPidOfSystem[id].find(element->getPid())
693 == mLastWorstPidOfSystem[id].end()))) {
694 mLastWorstPidOfSystem[id][element->getUid()] = it;
695 }
696 if ((!gc && !worstPid && (element->getUid() == worst))
697 || (mLastWorstUid[id].find(element->getUid())
698 == mLastWorstUid[id].end())) {
699 mLastWorstUid[id][element->getUid()] = it;
700 }
701 ++it;
702 continue;
703 }
704
705 if ((element->getUid() != worst)
706 || (worstPid && (element->getPid() != worstPid))) {
707 leading = false;
708 last.clear(element);
709 ++it;
710 continue;
711 }
712
713 pruneRows--;
714 if (pruneRows == 0) {
715 break;
716 }
717
718 kick = true;
719
720 unsigned short len = element->getMsgLen();
721
722 // do not create any leading drops
723 if (leading) {
724 it = erase(it);
725 } else {
726 stats.drop(element);
727 element->setDropped(1);
728 if (last.coalesce(element, 1)) {
729 it = erase(it, true);
730 } else {
731 last.add(element);
732 if (worstPid && (!gc
733 || (mLastWorstPidOfSystem[id].find(worstPid)
734 == mLastWorstPidOfSystem[id].end()))) {
735 mLastWorstPidOfSystem[id][worstPid] = it;
736 }
737 if ((!gc && !worstPid) || (mLastWorstUid[id].find(worst)
738 == mLastWorstUid[id].end())) {
739 mLastWorstUid[id][worst] = it;
740 }
741 ++it;
742 }
743 }
744 if (worst_sizes < second_worst_sizes) {
745 break;
746 }
747 worst_sizes -= len;
748 }
749 last.clear();
750
751 if (!kick || !mPrune.worstUidEnabled()) {
752 break; // the following loop will ask bad clients to skip/drop
753 }
754 }
755
756 bool whitelist = false;
757 bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll;
758 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
759 while((pruneRows > 0) && (it != mLogElements.end())) {
760 LogBufferElement *element = *it;
761
762 if (element->getLogId() != id) {
763 it++;
764 continue;
765 }
766
767 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
768 mLast[id] = it;
769 mLastSet[id] = true;
770 }
771
772 if (oldest && (oldest->mStart <= element->getSequence())) {
773 busy = true;
774 if (whitelist) {
775 break;
776 }
777
778 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
779 // kick a misbehaving log reader client off the island
780 oldest->release_Locked();
781 } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
782 oldest->triggerReader_Locked();
783 } else {
784 oldest->triggerSkip_Locked(id, pruneRows);
785 }
786 break;
787 }
788
789 if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) {
790 // WhiteListed
791 whitelist = true;
792 it++;
793 continue;
794 }
795
796 it = erase(it);
797 pruneRows--;
798 }
799
800 // Do not save the whitelist if we are reader range limited
801 if (whitelist && (pruneRows > 0)) {
802 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
803 while((it != mLogElements.end()) && (pruneRows > 0)) {
804 LogBufferElement *element = *it;
805
806 if (element->getLogId() != id) {
807 ++it;
808 continue;
809 }
810
811 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
812 mLast[id] = it;
813 mLastSet[id] = true;
814 }
815
816 if (oldest && (oldest->mStart <= element->getSequence())) {
817 busy = true;
818 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
819 // kick a misbehaving log reader client off the island
820 oldest->release_Locked();
821 } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
822 oldest->triggerReader_Locked();
823 } else {
824 oldest->triggerSkip_Locked(id, pruneRows);
825 }
826 break;
827 }
828
829 it = erase(it);
830 pruneRows--;
831 }
832 }
833
834 LogTimeEntry::unlock();
835
836 return (pruneRows > 0) && busy;
837 }
838
839 // clear all rows of type "id" from the buffer.
clear(log_id_t id,uid_t uid)840 bool LogBuffer::clear(log_id_t id, uid_t uid) {
841 bool busy = true;
842 // If it takes more than 4 tries (seconds) to clear, then kill reader(s)
843 for (int retry = 4;;) {
844 if (retry == 1) { // last pass
845 // Check if it is still busy after the sleep, we say prune
846 // one entry, not another clear run, so we are looking for
847 // the quick side effect of the return value to tell us if
848 // we have a _blocked_ reader.
849 pthread_mutex_lock(&mLogElementsLock);
850 busy = prune(id, 1, uid);
851 pthread_mutex_unlock(&mLogElementsLock);
852 // It is still busy, blocked reader(s), lets kill them all!
853 // otherwise, lets be a good citizen and preserve the slow
854 // readers and let the clear run (below) deal with determining
855 // if we are still blocked and return an error code to caller.
856 if (busy) {
857 LogTimeEntry::lock();
858 LastLogTimes::iterator times = mTimes.begin();
859 while (times != mTimes.end()) {
860 LogTimeEntry *entry = (*times);
861 // Killer punch
862 if (entry->owned_Locked() && entry->isWatching(id)) {
863 entry->release_Locked();
864 }
865 times++;
866 }
867 LogTimeEntry::unlock();
868 }
869 }
870 pthread_mutex_lock(&mLogElementsLock);
871 busy = prune(id, ULONG_MAX, uid);
872 pthread_mutex_unlock(&mLogElementsLock);
873 if (!busy || !--retry) {
874 break;
875 }
876 sleep (1); // Let reader(s) catch up after notification
877 }
878 return busy;
879 }
880
881 // get the used space associated with "id".
getSizeUsed(log_id_t id)882 unsigned long LogBuffer::getSizeUsed(log_id_t id) {
883 pthread_mutex_lock(&mLogElementsLock);
884 size_t retval = stats.sizes(id);
885 pthread_mutex_unlock(&mLogElementsLock);
886 return retval;
887 }
888
889 // set the total space allocated to "id"
setSize(log_id_t id,unsigned long size)890 int LogBuffer::setSize(log_id_t id, unsigned long size) {
891 // Reasonable limits ...
892 if (!valid_size(size)) {
893 return -1;
894 }
895 pthread_mutex_lock(&mLogElementsLock);
896 log_buffer_size(id) = size;
897 pthread_mutex_unlock(&mLogElementsLock);
898 return 0;
899 }
900
901 // get the total space allocated to "id"
getSize(log_id_t id)902 unsigned long LogBuffer::getSize(log_id_t id) {
903 pthread_mutex_lock(&mLogElementsLock);
904 size_t retval = log_buffer_size(id);
905 pthread_mutex_unlock(&mLogElementsLock);
906 return retval;
907 }
908
flushTo(SocketClient * reader,const uint64_t start,bool privileged,bool security,int (* filter)(const LogBufferElement * element,void * arg),void * arg)909 uint64_t LogBuffer::flushTo(
910 SocketClient *reader, const uint64_t start,
911 bool privileged, bool security,
912 int (*filter)(const LogBufferElement *element, void *arg), void *arg) {
913 LogBufferElementCollection::iterator it;
914 uint64_t max = start;
915 uid_t uid = reader->getUid();
916
917 pthread_mutex_lock(&mLogElementsLock);
918
919 if (start <= 1) {
920 // client wants to start from the beginning
921 it = mLogElements.begin();
922 } else {
923 // Client wants to start from some specified time. Chances are
924 // we are better off starting from the end of the time sorted list.
925 for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) {
926 --it;
927 LogBufferElement *element = *it;
928 if (element->getSequence() <= start) {
929 it++;
930 break;
931 }
932 }
933 }
934
935 for (; it != mLogElements.end(); ++it) {
936 LogBufferElement *element = *it;
937
938 if (!privileged && (element->getUid() != uid)) {
939 continue;
940 }
941
942 if (!security && (element->getLogId() == LOG_ID_SECURITY)) {
943 continue;
944 }
945
946 if (element->getSequence() <= start) {
947 continue;
948 }
949
950 // NB: calling out to another object with mLogElementsLock held (safe)
951 if (filter) {
952 int ret = (*filter)(element, arg);
953 if (ret == false) {
954 continue;
955 }
956 if (ret != true) {
957 break;
958 }
959 }
960
961 pthread_mutex_unlock(&mLogElementsLock);
962
963 // range locking in LastLogTimes looks after us
964 max = element->flushTo(reader, this, privileged);
965
966 if (max == element->FLUSH_ERROR) {
967 return max;
968 }
969
970 pthread_mutex_lock(&mLogElementsLock);
971 }
972 pthread_mutex_unlock(&mLogElementsLock);
973
974 return max;
975 }
976
formatStatistics(uid_t uid,pid_t pid,unsigned int logMask)977 std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid,
978 unsigned int logMask) {
979 pthread_mutex_lock(&mLogElementsLock);
980
981 std::string ret = stats.format(uid, pid, logMask);
982
983 pthread_mutex_unlock(&mLogElementsLock);
984
985 return ret;
986 }
987