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 <stdio.h>
19 #include <stdlib.h>
20 #include <string.h>
21 #include <sys/user.h>
22 #include <time.h>
23 #include <unistd.h>
24
25 #include <cutils/properties.h>
26 #include <log/logger.h>
27
28 #include "LogBuffer.h"
29 #include "LogReader.h"
30 #include "LogStatistics.h"
31 #include "LogWhiteBlackList.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
LogBuffer(LastLogTimes * times)95 LogBuffer::LogBuffer(LastLogTimes *times)
96 : mTimes(*times) {
97 pthread_mutex_init(&mLogElementsLock, NULL);
98 dgram_qlen_statistics = false;
99
100 static const char global_tuneable[] = "persist.logd.size"; // Settings App
101 static const char global_default[] = "ro.logd.size"; // BoardConfig.mk
102
103 unsigned long default_size = property_get_size(global_tuneable);
104 if (!default_size) {
105 default_size = property_get_size(global_default);
106 }
107
108 log_id_for_each(i) {
109 char key[PROP_NAME_MAX];
110
111 snprintf(key, sizeof(key), "%s.%s",
112 global_tuneable, android_log_id_to_name(i));
113 unsigned long property_size = property_get_size(key);
114
115 if (!property_size) {
116 snprintf(key, sizeof(key), "%s.%s",
117 global_default, android_log_id_to_name(i));
118 property_size = property_get_size(key);
119 }
120
121 if (!property_size) {
122 property_size = default_size;
123 }
124
125 if (!property_size) {
126 property_size = LOG_BUFFER_SIZE;
127 }
128
129 if (setSize(i, property_size)) {
130 setSize(i, LOG_BUFFER_MIN_SIZE);
131 }
132 }
133 }
134
log(log_id_t log_id,log_time realtime,uid_t uid,pid_t pid,pid_t tid,const char * msg,unsigned short len)135 void LogBuffer::log(log_id_t log_id, log_time realtime,
136 uid_t uid, pid_t pid, pid_t tid,
137 const char *msg, unsigned short len) {
138 if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
139 return;
140 }
141 LogBufferElement *elem = new LogBufferElement(log_id, realtime,
142 uid, pid, tid, msg, len);
143
144 pthread_mutex_lock(&mLogElementsLock);
145
146 // Insert elements in time sorted order if possible
147 // NB: if end is region locked, place element at end of list
148 LogBufferElementCollection::iterator it = mLogElements.end();
149 LogBufferElementCollection::iterator last = it;
150 while (--it != mLogElements.begin()) {
151 if ((*it)->getRealTime() <= realtime) {
152 // halves the peak performance, use with caution
153 if (dgram_qlen_statistics) {
154 LogBufferElementCollection::iterator ib = it;
155 unsigned short buckets, num = 1;
156 for (unsigned short i = 0; (buckets = stats.dgram_qlen(i)); ++i) {
157 buckets -= num;
158 num += buckets;
159 while (buckets && (--ib != mLogElements.begin())) {
160 --buckets;
161 }
162 if (buckets) {
163 break;
164 }
165 stats.recordDiff(
166 elem->getRealTime() - (*ib)->getRealTime(), i);
167 }
168 }
169 break;
170 }
171 last = it;
172 }
173
174 if (last == mLogElements.end()) {
175 mLogElements.push_back(elem);
176 } else {
177 log_time end = log_time::EPOCH;
178 bool end_set = false;
179 bool end_always = false;
180
181 LogTimeEntry::lock();
182
183 LastLogTimes::iterator t = mTimes.begin();
184 while(t != mTimes.end()) {
185 LogTimeEntry *entry = (*t);
186 if (entry->owned_Locked()) {
187 if (!entry->mNonBlock) {
188 end_always = true;
189 break;
190 }
191 if (!end_set || (end <= entry->mEnd)) {
192 end = entry->mEnd;
193 end_set = true;
194 }
195 }
196 t++;
197 }
198
199 if (end_always
200 || (end_set && (end >= (*last)->getMonotonicTime()))) {
201 mLogElements.push_back(elem);
202 } else {
203 mLogElements.insert(last,elem);
204 }
205
206 LogTimeEntry::unlock();
207 }
208
209 stats.add(len, log_id, uid, pid);
210 maybePrune(log_id);
211 pthread_mutex_unlock(&mLogElementsLock);
212 }
213
214 // If we're using more than 256K of memory for log entries, prune
215 // at least 10% of the log entries.
216 //
217 // mLogElementsLock must be held when this function is called.
maybePrune(log_id_t id)218 void LogBuffer::maybePrune(log_id_t id) {
219 size_t sizes = stats.sizes(id);
220 if (sizes > log_buffer_size(id)) {
221 size_t sizeOver90Percent = sizes - ((log_buffer_size(id) * 9) / 10);
222 size_t elements = stats.elements(id);
223 unsigned long pruneRows = elements * sizeOver90Percent / sizes;
224 elements /= 10;
225 if (pruneRows <= elements) {
226 pruneRows = elements;
227 }
228 prune(id, pruneRows);
229 }
230 }
231
232 // prune "pruneRows" of type "id" from the buffer.
233 //
234 // mLogElementsLock must be held when this function is called.
prune(log_id_t id,unsigned long pruneRows,uid_t caller_uid)235 void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
236 LogTimeEntry *oldest = NULL;
237
238 LogTimeEntry::lock();
239
240 // Region locked?
241 LastLogTimes::iterator t = mTimes.begin();
242 while(t != mTimes.end()) {
243 LogTimeEntry *entry = (*t);
244 if (entry->owned_Locked()
245 && (!oldest || (oldest->mStart > entry->mStart))) {
246 oldest = entry;
247 }
248 t++;
249 }
250
251 LogBufferElementCollection::iterator it;
252
253 if (caller_uid != AID_ROOT) {
254 for(it = mLogElements.begin(); it != mLogElements.end();) {
255 LogBufferElement *e = *it;
256
257 if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
258 break;
259 }
260
261 if (e->getLogId() != id) {
262 ++it;
263 continue;
264 }
265
266 uid_t uid = e->getUid();
267
268 if (uid == caller_uid) {
269 it = mLogElements.erase(it);
270 unsigned short len = e->getMsgLen();
271 stats.subtract(len, id, uid, e->getPid());
272 delete e;
273 pruneRows--;
274 if (pruneRows == 0) {
275 break;
276 }
277 } else {
278 ++it;
279 }
280 }
281 LogTimeEntry::unlock();
282 return;
283 }
284
285 // prune by worst offender by uid
286 while (pruneRows > 0) {
287 // recalculate the worst offender on every batched pass
288 uid_t worst = (uid_t) -1;
289 size_t worst_sizes = 0;
290 size_t second_worst_sizes = 0;
291
292 if ((id != LOG_ID_CRASH) && mPrune.worstUidEnabled()) {
293 LidStatistics &l = stats.id(id);
294 l.sort();
295 UidStatisticsCollection::iterator iu = l.begin();
296 if (iu != l.end()) {
297 UidStatistics *u = *iu;
298 worst = u->getUid();
299 worst_sizes = u->sizes();
300 if (++iu != l.end()) {
301 second_worst_sizes = (*iu)->sizes();
302 }
303 }
304 }
305
306 bool kick = false;
307 for(it = mLogElements.begin(); it != mLogElements.end();) {
308 LogBufferElement *e = *it;
309
310 if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
311 break;
312 }
313
314 if (e->getLogId() != id) {
315 ++it;
316 continue;
317 }
318
319 uid_t uid = e->getUid();
320
321 if (uid == worst) {
322 it = mLogElements.erase(it);
323 unsigned short len = e->getMsgLen();
324 stats.subtract(len, id, worst, e->getPid());
325 delete e;
326 kick = true;
327 pruneRows--;
328 if ((pruneRows == 0) || (worst_sizes < second_worst_sizes)) {
329 break;
330 }
331 worst_sizes -= len;
332 } else if (mPrune.naughty(e)) { // BlackListed
333 it = mLogElements.erase(it);
334 stats.subtract(e->getMsgLen(), id, uid, e->getPid());
335 delete e;
336 pruneRows--;
337 if (pruneRows == 0) {
338 break;
339 }
340 } else {
341 ++it;
342 }
343 }
344
345 if (!kick || !mPrune.worstUidEnabled()) {
346 break; // the following loop will ask bad clients to skip/drop
347 }
348 }
349
350 bool whitelist = false;
351 it = mLogElements.begin();
352 while((pruneRows > 0) && (it != mLogElements.end())) {
353 LogBufferElement *e = *it;
354 if (e->getLogId() == id) {
355 if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
356 if (!whitelist) {
357 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
358 // kick a misbehaving log reader client off the island
359 oldest->release_Locked();
360 } else {
361 oldest->triggerSkip_Locked(pruneRows);
362 }
363 }
364 break;
365 }
366
367 if (mPrune.nice(e)) { // WhiteListed
368 whitelist = true;
369 it++;
370 continue;
371 }
372
373 it = mLogElements.erase(it);
374 stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
375 delete e;
376 pruneRows--;
377 } else {
378 it++;
379 }
380 }
381
382 if (whitelist && (pruneRows > 0)) {
383 it = mLogElements.begin();
384 while((it != mLogElements.end()) && (pruneRows > 0)) {
385 LogBufferElement *e = *it;
386 if (e->getLogId() == id) {
387 if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
388 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
389 // kick a misbehaving log reader client off the island
390 oldest->release_Locked();
391 } else {
392 oldest->triggerSkip_Locked(pruneRows);
393 }
394 break;
395 }
396 it = mLogElements.erase(it);
397 stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
398 delete e;
399 pruneRows--;
400 } else {
401 it++;
402 }
403 }
404 }
405
406 LogTimeEntry::unlock();
407 }
408
409 // clear all rows of type "id" from the buffer.
clear(log_id_t id,uid_t uid)410 void LogBuffer::clear(log_id_t id, uid_t uid) {
411 pthread_mutex_lock(&mLogElementsLock);
412 prune(id, ULONG_MAX, uid);
413 pthread_mutex_unlock(&mLogElementsLock);
414 }
415
416 // get the used space associated with "id".
getSizeUsed(log_id_t id)417 unsigned long LogBuffer::getSizeUsed(log_id_t id) {
418 pthread_mutex_lock(&mLogElementsLock);
419 size_t retval = stats.sizes(id);
420 pthread_mutex_unlock(&mLogElementsLock);
421 return retval;
422 }
423
424 // set the total space allocated to "id"
setSize(log_id_t id,unsigned long size)425 int LogBuffer::setSize(log_id_t id, unsigned long size) {
426 // Reasonable limits ...
427 if (!valid_size(size)) {
428 return -1;
429 }
430 pthread_mutex_lock(&mLogElementsLock);
431 log_buffer_size(id) = size;
432 pthread_mutex_unlock(&mLogElementsLock);
433 return 0;
434 }
435
436 // get the total space allocated to "id"
getSize(log_id_t id)437 unsigned long LogBuffer::getSize(log_id_t id) {
438 pthread_mutex_lock(&mLogElementsLock);
439 size_t retval = log_buffer_size(id);
440 pthread_mutex_unlock(&mLogElementsLock);
441 return retval;
442 }
443
flushTo(SocketClient * reader,const log_time start,bool privileged,bool (* filter)(const LogBufferElement * element,void * arg),void * arg)444 log_time LogBuffer::flushTo(
445 SocketClient *reader, const log_time start, bool privileged,
446 bool (*filter)(const LogBufferElement *element, void *arg), void *arg) {
447 LogBufferElementCollection::iterator it;
448 log_time max = start;
449 uid_t uid = reader->getUid();
450
451 pthread_mutex_lock(&mLogElementsLock);
452 for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
453 LogBufferElement *element = *it;
454
455 if (!privileged && (element->getUid() != uid)) {
456 continue;
457 }
458
459 if (element->getMonotonicTime() <= start) {
460 continue;
461 }
462
463 // NB: calling out to another object with mLogElementsLock held (safe)
464 if (filter && !(*filter)(element, arg)) {
465 continue;
466 }
467
468 pthread_mutex_unlock(&mLogElementsLock);
469
470 // range locking in LastLogTimes looks after us
471 max = element->flushTo(reader);
472
473 if (max == element->FLUSH_ERROR) {
474 return max;
475 }
476
477 pthread_mutex_lock(&mLogElementsLock);
478 }
479 pthread_mutex_unlock(&mLogElementsLock);
480
481 return max;
482 }
483
formatStatistics(char ** strp,uid_t uid,unsigned int logMask)484 void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
485 log_time oldest(CLOCK_MONOTONIC);
486
487 pthread_mutex_lock(&mLogElementsLock);
488
489 // Find oldest element in the log(s)
490 LogBufferElementCollection::iterator it;
491 for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
492 LogBufferElement *element = *it;
493
494 if ((logMask & (1 << element->getLogId()))) {
495 oldest = element->getMonotonicTime();
496 break;
497 }
498 }
499
500 stats.format(strp, uid, logMask, oldest);
501
502 pthread_mutex_unlock(&mLogElementsLock);
503 }
504