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