blob: 0df6de086aa0b87c2c35a14654f6d1ceebcd25ae [file] [log] [blame]
Mark Salyzyn0175b072014-02-26 09:50:16 -08001/*
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 */
Mark Salyzyn60636fa2016-10-24 16:22:17 -070016// for manual checking of stale entries during LogBuffer::erase()
17//#define DEBUG_CHECK_FOR_STALE_ENTRIES
Mark Salyzyn0175b072014-02-26 09:50:16 -080018
Mark Salyzyn671e3432014-05-06 07:34:59 -070019#include <ctype.h>
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -080020#include <endian.h>
Mark Salyzyn202e1532015-02-09 08:21:05 -080021#include <errno.h>
Mark Salyzyn0175b072014-02-26 09:50:16 -080022#include <stdio.h>
23#include <string.h>
Mark Salyzyn8fcfd852016-10-24 08:20:26 -070024#include <sys/cdefs.h>
Mark Salyzyn57a0af92014-05-09 17:44:18 -070025#include <sys/user.h>
Mark Salyzyn0175b072014-02-26 09:50:16 -080026#include <time.h>
27#include <unistd.h>
28
Mark Salyzyn511338d2015-05-19 09:12:30 -070029#include <unordered_map>
30
Mark Salyzyn671e3432014-05-06 07:34:59 -070031#include <cutils/properties.h>
Mark Salyzynf10e2732016-09-27 13:08:23 -070032#include <private/android_logger.h>
Mark Salyzyn0175b072014-02-26 09:50:16 -080033
34#include "LogBuffer.h"
Mark Salyzynb6bee332015-09-08 08:56:32 -070035#include "LogKlog.h"
Mark Salyzyn671e3432014-05-06 07:34:59 -070036#include "LogReader.h"
Mark Salyzyna2c02222016-12-13 10:31:29 -080037#include "LogUtils.h"
Mark Salyzyn0175b072014-02-26 09:50:16 -080038
Mark Salyzyn8fcfd852016-10-24 08:20:26 -070039#ifndef __predict_false
40#define __predict_false(exp) __builtin_expect((exp) != 0, 0)
41#endif
42
Mark Salyzyndfa7a072014-02-11 12:29:31 -080043// Default
Mark Salyzyndfa7a072014-02-11 12:29:31 -080044#define log_buffer_size(id) mMaxSize[id]
Mark Salyzyn671e3432014-05-06 07:34:59 -070045
Mark Salyzyn11e55cb2015-03-10 16:45:17 -070046void LogBuffer::init() {
Mark Salyzyndfa7a072014-02-11 12:29:31 -080047 log_id_for_each(i) {
Mark Salyzyn507eb9f2016-01-11 10:58:09 -080048 mLastSet[i] = false;
49 mLast[i] = mLogElements.begin();
50
Mark Salyzynf10e2732016-09-27 13:08:23 -070051 if (setSize(i, __android_logger_get_buffer_size(i))) {
Mark Salyzyn57a0af92014-05-09 17:44:18 -070052 setSize(i, LOG_BUFFER_MIN_SIZE);
53 }
Mark Salyzyndfa7a072014-02-11 12:29:31 -080054 }
Mark Salyzynb6bee332015-09-08 08:56:32 -070055 bool lastMonotonic = monotonic;
Mark Salyzynba7a9a02015-12-01 15:57:25 -080056 monotonic = android_log_clockid() == CLOCK_MONOTONIC;
Mark Salyzynb75cce02015-11-30 11:35:56 -080057 if (lastMonotonic != monotonic) {
58 //
59 // Fixup all timestamps, may not be 100% accurate, but better than
60 // throwing what we have away when we get 'surprised' by a change.
61 // In-place element fixup so no need to check reader-lock. Entries
62 // should already be in timestamp order, but we could end up with a
63 // few out-of-order entries if new monotonics come in before we
64 // are notified of the reinit change in status. A Typical example would
65 // be:
66 // --------- beginning of system
67 // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
68 // --------- beginning of kernel
69 // 0.000000 0 0 I : Initializing cgroup subsys
70 // as the act of mounting /data would trigger persist.logd.timestamp to
71 // be corrected. 1/30 corner case YMMV.
72 //
73 pthread_mutex_lock(&mLogElementsLock);
74 LogBufferElementCollection::iterator it = mLogElements.begin();
75 while((it != mLogElements.end())) {
76 LogBufferElement *e = *it;
77 if (monotonic) {
78 if (!android::isMonotonic(e->mRealTime)) {
79 LogKlog::convertRealToMonotonic(e->mRealTime);
80 }
81 } else {
82 if (android::isMonotonic(e->mRealTime)) {
83 LogKlog::convertMonotonicToReal(e->mRealTime);
84 }
85 }
86 ++it;
87 }
88 pthread_mutex_unlock(&mLogElementsLock);
Mark Salyzynb6bee332015-09-08 08:56:32 -070089 }
90
Mark Salyzynb75cce02015-11-30 11:35:56 -080091 // We may have been triggered by a SIGHUP. Release any sleeping reader
92 // threads to dump their current content.
Mark Salyzynb6bee332015-09-08 08:56:32 -070093 //
Mark Salyzynb75cce02015-11-30 11:35:56 -080094 // NB: this is _not_ performed in the context of a SIGHUP, it is
95 // performed during startup, and in context of reinit administrative thread
96 LogTimeEntry::lock();
97
98 LastLogTimes::iterator times = mTimes.begin();
99 while(times != mTimes.end()) {
100 LogTimeEntry *entry = (*times);
101 if (entry->owned_Locked()) {
102 entry->triggerReader_Locked();
Mark Salyzynb6bee332015-09-08 08:56:32 -0700103 }
Mark Salyzynb75cce02015-11-30 11:35:56 -0800104 times++;
Mark Salyzynb6bee332015-09-08 08:56:32 -0700105 }
Mark Salyzynb75cce02015-11-30 11:35:56 -0800106
107 LogTimeEntry::unlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -0800108}
109
Mark Salyzynb6bee332015-09-08 08:56:32 -0700110LogBuffer::LogBuffer(LastLogTimes *times):
Mark Salyzynba7a9a02015-12-01 15:57:25 -0800111 monotonic(android_log_clockid() == CLOCK_MONOTONIC),
Mark Salyzynb6bee332015-09-08 08:56:32 -0700112 mTimes(*times) {
Mark Salyzyn11e55cb2015-03-10 16:45:17 -0700113 pthread_mutex_init(&mLogElementsLock, NULL);
114
Mark Salyzyna2c02222016-12-13 10:31:29 -0800115 log_id_for_each(i) {
116 lastLoggedElements[i] = NULL;
117 droppedElements[i] = NULL;
118 }
119
Mark Salyzyn11e55cb2015-03-10 16:45:17 -0700120 init();
121}
122
Mark Salyzyna2c02222016-12-13 10:31:29 -0800123LogBuffer::~LogBuffer() {
124 log_id_for_each(i) {
125 delete lastLoggedElements[i];
126 delete droppedElements[i];
127 }
128}
129
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800130enum match_type {
131 DIFFERENT,
132 SAME,
133 SAME_LIBLOG
134};
135
136static enum match_type identical(LogBufferElement* elem, LogBufferElement* last) {
Mark Salyzyna2c02222016-12-13 10:31:29 -0800137 // is it mostly identical?
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800138// if (!elem) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800139 unsigned short lenl = elem->getMsgLen();
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800140 if (!lenl) return DIFFERENT;
141// if (!last) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800142 unsigned short lenr = last->getMsgLen();
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800143 if (!lenr) return DIFFERENT;
144// if (elem->getLogId() != last->getLogId()) return DIFFERENT;
145 if (elem->getUid() != last->getUid()) return DIFFERENT;
146 if (elem->getPid() != last->getPid()) return DIFFERENT;
147 if (elem->getTid() != last->getTid()) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800148
149 // last is more than a minute old, stop squashing identical messages
150 if (elem->getRealTime().nsec() >
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800151 (last->getRealTime().nsec() + 60 * NS_PER_SEC)) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800152
153 // Identical message
154 const char* msgl = elem->getMsg();
155 const char* msgr = last->getMsg();
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800156 if (lenl == lenr) {
157 if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME;
158 // liblog tagged messages (content gets summed)
159 if ((elem->getLogId() == LOG_ID_EVENTS) &&
160 (lenl == sizeof(android_log_event_int_t)) &&
161 !fastcmp<memcmp>(msgl, msgr,
162 sizeof(android_log_event_int_t) - sizeof(int32_t)) &&
163 (elem->getTag() == LIBLOG_LOG_TAG)) return SAME_LIBLOG;
164 }
Mark Salyzyna2c02222016-12-13 10:31:29 -0800165
166 // audit message (except sequence number) identical?
167 static const char avc[] = "): avc: ";
168
169 if (last->isBinary()) {
170 if (fastcmp<memcmp>(msgl, msgr,
171 sizeof(android_log_event_string_t) -
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800172 sizeof(int32_t))) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800173 msgl += sizeof(android_log_event_string_t);
174 lenl -= sizeof(android_log_event_string_t);
175 msgr += sizeof(android_log_event_string_t);
176 lenr -= sizeof(android_log_event_string_t);
177 }
178 const char *avcl = android::strnstr(msgl, lenl, avc);
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800179 if (!avcl) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800180 lenl -= avcl - msgl;
181 const char *avcr = android::strnstr(msgr, lenr, avc);
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800182 if (!avcr) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800183 lenr -= avcr - msgr;
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800184 if (lenl != lenr) return DIFFERENT;
Alex Shlyapnikov589f4e72017-02-14 17:21:55 -0800185 // TODO: After b/35468874 is addressed, revisit "lenl > strlen(avc)"
186 // condition, it might become superflous.
187 if (lenl > strlen(avc) &&
188 fastcmp<memcmp>(avcl + strlen(avc),
Greg Hartmana6754dd2017-02-15 21:43:30 -0800189 avcr + strlen(avc),
190 lenl - strlen(avc))) return DIFFERENT;
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800191 return SAME;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800192}
193
Mark Salyzyn202e1532015-02-09 08:21:05 -0800194int LogBuffer::log(log_id_t log_id, log_time realtime,
195 uid_t uid, pid_t pid, pid_t tid,
196 const char *msg, unsigned short len) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800197 if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
Mark Salyzyn202e1532015-02-09 08:21:05 -0800198 return -EINVAL;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800199 }
Mark Salyzyne59c4692014-10-02 13:07:05 -0700200
Mark Salyzyn0175b072014-02-26 09:50:16 -0800201 LogBufferElement *elem = new LogBufferElement(log_id, realtime,
Mark Salyzynb992d0d2014-03-20 16:09:38 -0700202 uid, pid, tid, msg, len);
Mark Salyzyn0ee8de32016-01-06 21:17:43 +0000203 if (log_id != LOG_ID_SECURITY) {
Mark Salyzyn083b0372015-12-04 10:59:45 -0800204 int prio = ANDROID_LOG_INFO;
Mark Salyzyn0ee8de32016-01-06 21:17:43 +0000205 const char *tag = NULL;
Mark Salyzyn083b0372015-12-04 10:59:45 -0800206 if (log_id == LOG_ID_EVENTS) {
Mark Salyzyn61e9ce62016-09-12 14:51:54 -0700207 tag = tagToName(elem->getTag());
Mark Salyzyn083b0372015-12-04 10:59:45 -0800208 } else {
209 prio = *msg;
210 tag = msg + 1;
211 }
Mark Salyzyn61e9ce62016-09-12 14:51:54 -0700212 if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) {
Mark Salyzyn083b0372015-12-04 10:59:45 -0800213 // Log traffic received to total
214 pthread_mutex_lock(&mLogElementsLock);
215 stats.add(elem);
216 stats.subtract(elem);
217 pthread_mutex_unlock(&mLogElementsLock);
218 delete elem;
219 return -EACCES;
220 }
Mark Salyzyne59c4692014-10-02 13:07:05 -0700221 }
Mark Salyzyn0175b072014-02-26 09:50:16 -0800222
223 pthread_mutex_lock(&mLogElementsLock);
Mark Salyzyna2c02222016-12-13 10:31:29 -0800224 LogBufferElement* currentLast = lastLoggedElements[log_id];
225 if (currentLast) {
226 LogBufferElement *dropped = droppedElements[log_id];
227 unsigned short count = dropped ? dropped->getDropped() : 0;
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800228 //
229 // State Init
230 // incoming:
231 // dropped = NULL
232 // currentLast = NULL;
233 // elem = incoming message
234 // outgoing:
235 // dropped = NULL -> State 0
236 // currentLast = copy of elem
237 // log elem
238 // State 0
239 // incoming:
240 // count = 0
241 // dropped = NULL
242 // currentLast = copy of last message
243 // elem = incoming message
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800244 // outgoing: if match != DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800245 // dropped = copy of first identical message -> State 1
246 // currentLast = reference to elem
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800247 // break: if match == DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800248 // dropped = NULL -> State 0
249 // delete copy of last message (incoming currentLast)
250 // currentLast = copy of elem
251 // log elem
252 // State 1
253 // incoming:
254 // count = 0
255 // dropped = copy of first identical message
256 // currentLast = reference to last held-back incoming
257 // message
258 // elem = incoming message
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800259 // outgoing: if match == SAME
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800260 // delete copy of first identical message (dropped)
261 // dropped = reference to last held-back incoming
262 // message set to chatty count of 1 -> State 2
263 // currentLast = reference to elem
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800264 // outgoing: if match == SAME_LIBLOG
265 // dropped = copy of first identical message -> State 1
266 // take sum of currentLast and elem
267 // if sum overflows:
268 // log currentLast
269 // currentLast = reference to elem
270 // else
271 // delete currentLast
272 // currentLast = reference to elem, sum liblog.
273 // break: if match == DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800274 // delete dropped
275 // dropped = NULL -> State 0
276 // log reference to last held-back (currentLast)
277 // currentLast = copy of elem
278 // log elem
279 // State 2
280 // incoming:
281 // count = chatty count
282 // dropped = chatty message holding count
283 // currentLast = reference to last held-back incoming
284 // message.
285 // dropped = chatty message holding count
286 // elem = incoming message
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800287 // outgoing: if match != DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800288 // delete chatty message holding count
289 // dropped = reference to last held-back incoming
290 // message, set to chatty count + 1
291 // currentLast = reference to elem
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800292 // break: if match == DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800293 // log dropped (chatty message)
294 // dropped = NULL -> State 0
295 // log reference to last held-back (currentLast)
296 // currentLast = copy of elem
297 // log elem
298 //
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800299 enum match_type match = identical(elem, currentLast);
300 if (match != DIFFERENT) {
Mark Salyzyna2c02222016-12-13 10:31:29 -0800301 if (dropped) {
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800302 // Sum up liblog tag messages?
303 if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) {
304 android_log_event_int_t* event =
305 reinterpret_cast<android_log_event_int_t*>(
306 const_cast<char*>(currentLast->getMsg()));
307 //
308 // To unit test, differentiate with something like:
309 // event->header.tag = htole32(CHATTY_LOG_TAG);
310 // here, then instead of delete currentLast below,
311 // log(currentLast) to see the incremental sums form.
312 //
313 uint32_t swab = event->payload.data;
314 unsigned long long total = htole32(swab);
315 event = reinterpret_cast<android_log_event_int_t*>(
316 const_cast<char*>(elem->getMsg()));
317 swab = event->payload.data;
318
319 lastLoggedElements[LOG_ID_EVENTS] = elem;
320 total += htole32(swab);
321 // check for overflow
322 if (total >= UINT32_MAX) {
323 log(currentLast);
324 pthread_mutex_unlock(&mLogElementsLock);
325 return len;
326 }
327 stats.add(currentLast);
328 stats.subtract(currentLast);
329 delete currentLast;
330 swab = total;
331 event->payload.data = htole32(swab);
332 pthread_mutex_unlock(&mLogElementsLock);
333 return len;
334 }
Mark Salyzyna2c02222016-12-13 10:31:29 -0800335 if (count == USHRT_MAX) {
336 log(dropped);
337 count = 1;
338 } else {
339 delete dropped;
340 ++count;
341 }
342 }
343 if (count) {
344 stats.add(currentLast);
345 stats.subtract(currentLast);
346 currentLast->setDropped(count);
347 }
348 droppedElements[log_id] = currentLast;
349 lastLoggedElements[log_id] = elem;
350 pthread_mutex_unlock(&mLogElementsLock);
351 return len;
352 }
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800353 if (dropped) { // State 1 or 2
354 if (count) { // State 2
355 log(dropped); // report chatty
356 } else { // State 1
357 delete dropped;
358 }
Mark Salyzyna2c02222016-12-13 10:31:29 -0800359 droppedElements[log_id] = NULL;
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800360 log(currentLast); // report last message in the series
361 } else { // State 0
Mark Salyzyna2c02222016-12-13 10:31:29 -0800362 delete currentLast;
363 }
364 }
365 lastLoggedElements[log_id] = new LogBufferElement(*elem);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800366
Mark Salyzyna2c02222016-12-13 10:31:29 -0800367 log(elem);
368 pthread_mutex_unlock(&mLogElementsLock);
369
370 return len;
371}
372
373// assumes mLogElementsLock held, owns elem, will look after garbage collection
374void LogBuffer::log(LogBufferElement* elem) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800375 // Insert elements in time sorted order if possible
376 // NB: if end is region locked, place element at end of list
377 LogBufferElementCollection::iterator it = mLogElements.end();
378 LogBufferElementCollection::iterator last = it;
Mark Salyzyneae155e2014-10-13 16:49:47 -0700379 while (last != mLogElements.begin()) {
380 --it;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800381 if ((*it)->getRealTime() <= elem->getRealTime()) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800382 break;
383 }
384 last = it;
385 }
Mark Salyzync03e72c2014-02-18 11:23:53 -0800386
Mark Salyzyn0175b072014-02-26 09:50:16 -0800387 if (last == mLogElements.end()) {
388 mLogElements.push_back(elem);
389 } else {
Mark Salyzynf7c0f752015-03-03 13:39:37 -0800390 uint64_t end = 1;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800391 bool end_set = false;
392 bool end_always = false;
393
394 LogTimeEntry::lock();
395
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700396 LastLogTimes::iterator times = mTimes.begin();
397 while(times != mTimes.end()) {
Mark Salyzyna2c02222016-12-13 10:31:29 -0800398 LogTimeEntry* entry = (*times);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800399 if (entry->owned_Locked()) {
400 if (!entry->mNonBlock) {
401 end_always = true;
402 break;
403 }
404 if (!end_set || (end <= entry->mEnd)) {
405 end = entry->mEnd;
406 end_set = true;
407 }
408 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700409 times++;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800410 }
411
412 if (end_always
Mark Salyzynf7c0f752015-03-03 13:39:37 -0800413 || (end_set && (end >= (*last)->getSequence()))) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800414 mLogElements.push_back(elem);
415 } else {
Mark Salyzyna2c02222016-12-13 10:31:29 -0800416 mLogElements.insert(last, elem);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800417 }
418
419 LogTimeEntry::unlock();
420 }
421
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700422 stats.add(elem);
Mark Salyzyna2c02222016-12-13 10:31:29 -0800423 maybePrune(elem->getLogId());
Mark Salyzyn0175b072014-02-26 09:50:16 -0800424}
425
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700426// Prune at most 10% of the log entries or maxPrune, whichever is less.
Mark Salyzyn0175b072014-02-26 09:50:16 -0800427//
428// mLogElementsLock must be held when this function is called.
429void LogBuffer::maybePrune(log_id_t id) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800430 size_t sizes = stats.sizes(id);
Mark Salyzyn62ab0fd2015-08-10 10:23:56 -0700431 unsigned long maxSize = log_buffer_size(id);
432 if (sizes > maxSize) {
Mark Salyzynb39ed0c2015-08-19 12:20:36 -0700433 size_t sizeOver = sizes - ((maxSize * 9) / 10);
Mark Salyzyn58b8be82015-09-30 07:40:09 -0700434 size_t elements = stats.realElements(id);
435 size_t minElements = elements / 100;
436 if (minElements < minPrune) {
437 minElements = minPrune;
438 }
Mark Salyzyn62ab0fd2015-08-10 10:23:56 -0700439 unsigned long pruneRows = elements * sizeOver / sizes;
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700440 if (pruneRows < minElements) {
Mark Salyzyn62ab0fd2015-08-10 10:23:56 -0700441 pruneRows = minElements;
Mark Salyzyn740f9b42014-01-13 16:37:51 -0800442 }
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700443 if (pruneRows > maxPrune) {
444 pruneRows = maxPrune;
Mark Salyzynb39ed0c2015-08-19 12:20:36 -0700445 }
Mark Salyzyn740f9b42014-01-13 16:37:51 -0800446 prune(id, pruneRows);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800447 }
448}
449
Mark Salyzyn831aa292015-09-03 16:08:50 -0700450LogBufferElementCollection::iterator LogBuffer::erase(
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700451 LogBufferElementCollection::iterator it, bool coalesce) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700452 LogBufferElement *element = *it;
453 log_id_t id = element->getLogId();
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700454
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700455 // Remove iterator references in the various lists that will become stale
456 // after the element is erased from the main logging list.
457
Mark Salyzyn6a066942016-07-14 15:34:30 -0700458 { // start of scope for found iterator
459 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) ?
460 element->getTag() : element->getUid();
461 LogBufferIteratorMap::iterator found = mLastWorst[id].find(key);
462 if ((found != mLastWorst[id].end()) && (it == found->second)) {
463 mLastWorst[id].erase(found);
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700464 }
Mark Salyzync892ea32015-08-19 17:06:11 -0700465 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700466
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700467 { // start of scope for pid found iterator
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700468 // element->getUid() may not be AID_SYSTEM for next-best-watermark.
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700469 // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and
470 // long term code stability, find() check should be fast for those ids.
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700471 LogBufferPidIteratorMap::iterator found =
472 mLastWorstPidOfSystem[id].find(element->getPid());
473 if ((found != mLastWorstPidOfSystem[id].end())
474 && (it == found->second)) {
475 mLastWorstPidOfSystem[id].erase(found);
476 }
477 }
478
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800479 bool setLast[LOG_ID_MAX];
480 bool doSetLast = false;
481 log_id_for_each(i) {
482 doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]);
483 }
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700484#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
485 LogBufferElementCollection::iterator bad = it;
486 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) ?
487 element->getTag() : element->getUid();
488#endif
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700489 it = mLogElements.erase(it);
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800490 if (doSetLast) {
491 log_id_for_each(i) {
492 if (setLast[i]) {
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700493 if (__predict_false(it == mLogElements.end())) { // impossible
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800494 mLastSet[i] = false;
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700495 mLast[i] = mLogElements.begin();
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800496 } else {
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700497 mLast[i] = it; // push down the road as next-best-watermark
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800498 }
499 }
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800500 }
501 }
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700502#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
503 log_id_for_each(i) {
504 for(auto b : mLastWorst[i]) {
505 if (bad == b.second) {
506 android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n",
507 i, b.first, key);
508 }
509 }
510 for(auto b : mLastWorstPidOfSystem[i]) {
511 if (bad == b.second) {
512 android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n",
513 i, b.first);
514 }
515 }
516 if (mLastSet[i] && (bad == mLast[i])) {
517 android::prdebug("stale mLast[%d]\n", i);
518 mLastSet[i] = false;
519 mLast[i] = mLogElements.begin();
520 }
521 }
522#endif
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700523 if (coalesce) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700524 stats.erase(element);
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700525 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700526 stats.subtract(element);
Mark Salyzyn831aa292015-09-03 16:08:50 -0700527 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700528 delete element;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700529
530 return it;
531}
532
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700533// Define a temporary mechanism to report the last LogBufferElement pointer
534// for the specified uid, pid and tid. Used below to help merge-sort when
535// pruning for worst UID.
536class LogBufferElementKey {
537 const union {
538 struct {
Mark Salyzyn684bdb52016-12-13 12:44:20 -0800539 uint32_t uid;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700540 uint16_t pid;
541 uint16_t tid;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700542 } __packed;
543 uint64_t value;
544 } __packed;
545
546public:
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700547 LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid):
548 uid(uid),
549 pid(pid),
Mark Salyzyn684bdb52016-12-13 12:44:20 -0800550 tid(tid)
551 {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700552 }
Chih-Hung Hsieh1cc82ce2016-04-25 13:49:46 -0700553 explicit LogBufferElementKey(uint64_t key):value(key) { }
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700554
555 uint64_t getKey() { return value; }
556};
557
Mark Salyzyn511338d2015-05-19 09:12:30 -0700558class LogBufferElementLast {
559
560 typedef std::unordered_map<uint64_t, LogBufferElement *> LogBufferElementMap;
561 LogBufferElementMap map;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700562
563public:
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700564
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700565 bool coalesce(LogBufferElement *element, unsigned short dropped) {
566 LogBufferElementKey key(element->getUid(),
567 element->getPid(),
568 element->getTid());
Mark Salyzyn511338d2015-05-19 09:12:30 -0700569 LogBufferElementMap::iterator it = map.find(key.getKey());
570 if (it != map.end()) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700571 LogBufferElement *found = it->second;
572 unsigned short moreDropped = found->getDropped();
573 if ((dropped + moreDropped) > USHRT_MAX) {
Mark Salyzyn511338d2015-05-19 09:12:30 -0700574 map.erase(it);
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700575 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700576 found->setDropped(dropped + moreDropped);
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700577 return true;
578 }
579 }
580 return false;
581 }
582
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700583 void add(LogBufferElement *element) {
584 LogBufferElementKey key(element->getUid(),
585 element->getPid(),
586 element->getTid());
587 map[key.getKey()] = element;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700588 }
589
Mark Salyzyne06a6e02015-04-20 14:08:56 -0700590 inline void clear() {
Mark Salyzyn511338d2015-05-19 09:12:30 -0700591 map.clear();
Mark Salyzyne06a6e02015-04-20 14:08:56 -0700592 }
593
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700594 void clear(LogBufferElement *element) {
595 uint64_t current = element->getRealTime().nsec()
Mark Salyzyn047cc072015-06-04 13:35:30 -0700596 - (EXPIRE_RATELIMIT * NS_PER_SEC);
Mark Salyzyn511338d2015-05-19 09:12:30 -0700597 for(LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700598 LogBufferElement *mapElement = it->second;
599 if ((mapElement->getDropped() >= EXPIRE_THRESHOLD)
600 && (current > mapElement->getRealTime().nsec())) {
Mark Salyzyn511338d2015-05-19 09:12:30 -0700601 it = map.erase(it);
602 } else {
603 ++it;
Mark Salyzyne06a6e02015-04-20 14:08:56 -0700604 }
605 }
606 }
607
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700608};
609
Mark Salyzyn0175b072014-02-26 09:50:16 -0800610// prune "pruneRows" of type "id" from the buffer.
611//
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700612// This garbage collection task is used to expire log entries. It is called to
613// remove all logs (clear), all UID logs (unprivileged clear), or every
614// 256 or 10% of the total logs (whichever is less) to prune the logs.
615//
616// First there is a prep phase where we discover the reader region lock that
617// acts as a backstop to any pruning activity to stop there and go no further.
618//
619// There are three major pruning loops that follow. All expire from the oldest
620// entries. Since there are multiple log buffers, the Android logging facility
621// will appear to drop entries 'in the middle' when looking at multiple log
622// sources and buffers. This effect is slightly more prominent when we prune
623// the worst offender by logging source. Thus the logs slowly loose content
624// and value as you move back in time. This is preferred since chatty sources
625// invariably move the logs value down faster as less chatty sources would be
626// expired in the noise.
627//
628// The first loop performs blacklisting and worst offender pruning. Falling
629// through when there are no notable worst offenders and have not hit the
630// region lock preventing further worst offender pruning. This loop also looks
631// after managing the chatty log entries and merging to help provide
632// statistical basis for blame. The chatty entries are not a notification of
633// how much logs you may have, but instead represent how much logs you would
634// have had in a virtual log buffer that is extended to cover all the in-memory
635// logs without loss. They last much longer than the represented pruned logs
636// since they get multiplied by the gains in the non-chatty log sources.
637//
638// The second loop get complicated because an algorithm of watermarks and
639// history is maintained to reduce the order and keep processing time
640// down to a minimum at scale. These algorithms can be costly in the face
641// of larger log buffers, or severly limited processing time granted to a
642// background task at lowest priority.
643//
644// This second loop does straight-up expiration from the end of the logs
645// (again, remember for the specified log buffer id) but does some whitelist
646// preservation. Thus whitelist is a Hail Mary low priority, blacklists and
647// spam filtration all take priority. This second loop also checks if a region
648// lock is causing us to buffer too much in the logs to help the reader(s),
649// and will tell the slowest reader thread to skip log entries, and if
650// persistent and hits a further threshold, kill the reader thread.
651//
652// The third thread is optional, and only gets hit if there was a whitelist
653// and more needs to be pruned against the backstop of the region lock.
654//
Mark Salyzyn0175b072014-02-26 09:50:16 -0800655// mLogElementsLock must be held when this function is called.
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700656//
Mark Salyzync5dc9702015-09-16 15:34:00 -0700657bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800658 LogTimeEntry *oldest = NULL;
Mark Salyzync5dc9702015-09-16 15:34:00 -0700659 bool busy = false;
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700660 bool clearAll = pruneRows == ULONG_MAX;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800661
662 LogTimeEntry::lock();
663
664 // Region locked?
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700665 LastLogTimes::iterator times = mTimes.begin();
666 while(times != mTimes.end()) {
667 LogTimeEntry *entry = (*times);
TraianX Schiauda6495d2014-12-17 10:53:41 +0200668 if (entry->owned_Locked() && entry->isWatching(id)
Mark Salyzynb75cce02015-11-30 11:35:56 -0800669 && (!oldest ||
670 (oldest->mStart > entry->mStart) ||
671 ((oldest->mStart == entry->mStart) &&
672 (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800673 oldest = entry;
674 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700675 times++;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800676 }
677
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800678 LogBufferElementCollection::iterator it;
679
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700680 if (__predict_false(caller_uid != AID_ROOT)) { // unlikely
Mark Salyzyn43a5f312016-09-01 15:48:36 -0700681 // Only here if clear all request from non system source, so chatty
682 // filter logistics is not required.
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800683 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
684 while (it != mLogElements.end()) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700685 LogBufferElement *element = *it;
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700686
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700687 if ((element->getLogId() != id) || (element->getUid() != caller_uid)) {
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700688 ++it;
689 continue;
690 }
691
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800692 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
693 mLast[id] = it;
694 mLastSet[id] = true;
695 }
696
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700697 if (oldest && (oldest->mStart <= element->getSequence())) {
Mark Salyzync5dc9702015-09-16 15:34:00 -0700698 busy = true;
Mark Salyzynb75cce02015-11-30 11:35:56 -0800699 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
700 oldest->triggerReader_Locked();
701 } else {
702 oldest->triggerSkip_Locked(id, pruneRows);
703 }
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700704 break;
705 }
706
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700707 it = erase(it);
Mark Salyzyn43a5f312016-09-01 15:48:36 -0700708 if (--pruneRows == 0) {
709 break;
710 }
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700711 }
712 LogTimeEntry::unlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -0700713 return busy;
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700714 }
715
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700716 // prune by worst offenders; by blacklist, UID, and by PID of system UID
Mark Salyzyn083b0372015-12-04 10:59:45 -0800717 bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty();
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700718 while (!clearAll && (pruneRows > 0)) {
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800719 // recalculate the worst offender on every batched pass
Mark Salyzyn6a066942016-07-14 15:34:30 -0700720 int worst = -1; // not valid for getUid() or getKey()
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800721 size_t worst_sizes = 0;
722 size_t second_worst_sizes = 0;
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700723 pid_t worstPid = 0; // POSIX guarantees PID != 0
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800724
Mark Salyzynae769232015-03-17 17:17:25 -0700725 if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) {
Mark Salyzyn6a066942016-07-14 15:34:30 -0700726 // Calculate threshold as 12.5% of available storage
727 size_t threshold = log_buffer_size(id) / 8;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700728
Mark Salyzyn6a066942016-07-14 15:34:30 -0700729 if ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) {
730 stats.sortTags(AID_ROOT, (pid_t)0, 2, id).findWorst(
731 worst, worst_sizes, second_worst_sizes, threshold);
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700732 // per-pid filter for AID_SYSTEM sources is too complex
Mark Salyzyn6a066942016-07-14 15:34:30 -0700733 } else {
734 stats.sort(AID_ROOT, (pid_t)0, 2, id).findWorst(
735 worst, worst_sizes, second_worst_sizes, threshold);
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700736
Mark Salyzyn6a066942016-07-14 15:34:30 -0700737 if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) {
738 stats.sortPids(worst, (pid_t)0, 2, id).findWorst(
739 worstPid, worst_sizes, second_worst_sizes);
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700740 }
741 }
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800742 }
743
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700744 // skip if we have neither worst nor naughty filters
Mark Salyzyn6a066942016-07-14 15:34:30 -0700745 if ((worst == -1) && !hasBlacklist) {
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700746 break;
747 }
748
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800749 bool kick = false;
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700750 bool leading = true;
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800751 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700752 // Perform at least one mandatory garbage collection cycle in following
753 // - clear leading chatty tags
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700754 // - coalesce chatty tags
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700755 // - check age-out of preserved logs
756 bool gc = pruneRows <= 1;
Mark Salyzyn6a066942016-07-14 15:34:30 -0700757 if (!gc && (worst != -1)) {
758 { // begin scope for worst found iterator
759 LogBufferIteratorMap::iterator found = mLastWorst[id].find(worst);
760 if ((found != mLastWorst[id].end())
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700761 && (found->second != mLogElements.end())) {
762 leading = false;
763 it = found->second;
764 }
765 }
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700766 if (worstPid) { // begin scope for pid worst found iterator
767 // FYI: worstPid only set if !LOG_ID_EVENTS and
768 // !LOG_ID_SECURITY, not going to make that assumption ...
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700769 LogBufferPidIteratorMap::iterator found
770 = mLastWorstPidOfSystem[id].find(worstPid);
771 if ((found != mLastWorstPidOfSystem[id].end())
772 && (found->second != mLogElements.end())) {
773 leading = false;
774 it = found->second;
775 }
Mark Salyzync892ea32015-08-19 17:06:11 -0700776 }
777 }
Mark Salyzynccfe8442015-08-24 13:43:27 -0700778 static const timespec too_old = {
779 EXPIRE_HOUR_THRESHOLD * 60 * 60, 0
780 };
781 LogBufferElementCollection::iterator lastt;
782 lastt = mLogElements.end();
783 --lastt;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700784 LogBufferElementLast last;
Mark Salyzync892ea32015-08-19 17:06:11 -0700785 while (it != mLogElements.end()) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700786 LogBufferElement *element = *it;
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800787
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700788 if (oldest && (oldest->mStart <= element->getSequence())) {
Mark Salyzync5dc9702015-09-16 15:34:00 -0700789 busy = true;
Mark Salyzynb75cce02015-11-30 11:35:56 -0800790 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
791 oldest->triggerReader_Locked();
792 }
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800793 break;
794 }
795
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700796 if (element->getLogId() != id) {
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800797 ++it;
798 continue;
799 }
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700800 // below this point element->getLogId() == id
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800801
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800802 if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) {
803 mLast[id] = it;
804 mLastSet[id] = true;
805 }
806
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700807 unsigned short dropped = element->getDropped();
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800808
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700809 // remove any leading drops
810 if (leading && dropped) {
811 it = erase(it);
812 continue;
813 }
814
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700815 if (dropped && last.coalesce(element, dropped)) {
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700816 it = erase(it, true);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700817 continue;
818 }
819
Mark Salyzyn6a066942016-07-14 15:34:30 -0700820 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) ?
821 element->getTag() :
822 element->getUid();
823
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700824 if (hasBlacklist && mPrune.naughty(element)) {
825 last.clear(element);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700826 it = erase(it);
827 if (dropped) {
828 continue;
829 }
830
831 pruneRows--;
832 if (pruneRows == 0) {
833 break;
834 }
835
Mark Salyzyn6a066942016-07-14 15:34:30 -0700836 if (key == worst) {
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700837 kick = true;
838 if (worst_sizes < second_worst_sizes) {
839 break;
840 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700841 worst_sizes -= element->getMsgLen();
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700842 }
843 continue;
844 }
845
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700846 if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old))
847 || (element->getRealTime() > (*lastt)->getRealTime())) {
Mark Salyzynccfe8442015-08-24 13:43:27 -0700848 break;
849 }
850
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700851 if (dropped) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700852 last.add(element);
853 if (worstPid
854 && ((!gc && (element->getPid() == worstPid))
Mark Salyzyn6a066942016-07-14 15:34:30 -0700855 || (mLastWorstPidOfSystem[id].find(element->getPid())
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700856 == mLastWorstPidOfSystem[id].end()))) {
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700857 // element->getUid() may not be AID_SYSTEM, next best
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700858 // watermark if current one empty. id is not LOG_ID_EVENTS
859 // or LOG_ID_SECURITY because of worstPid check.
Mark Salyzyn1eefca22016-09-01 07:28:44 -0700860 mLastWorstPidOfSystem[id][element->getPid()] = it;
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700861 }
Mark Salyzyn6a066942016-07-14 15:34:30 -0700862 if ((!gc && !worstPid && (key == worst))
863 || (mLastWorst[id].find(key) == mLastWorst[id].end())) {
864 mLastWorst[id][key] = it;
Mark Salyzyn49afe0d2015-08-24 13:43:27 -0700865 }
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800866 ++it;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700867 continue;
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800868 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700869
Mark Salyzyn6a066942016-07-14 15:34:30 -0700870 if ((key != worst)
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700871 || (worstPid && (element->getPid() != worstPid))) {
Mark Salyzyn59212762015-06-01 09:41:19 -0700872 leading = false;
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700873 last.clear(element);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700874 ++it;
875 continue;
876 }
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700877 // key == worst below here
878 // If worstPid set, then element->getPid() == worstPid below here
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700879
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700880 pruneRows--;
881 if (pruneRows == 0) {
882 break;
883 }
884
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700885 kick = true;
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700886
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700887 unsigned short len = element->getMsgLen();
Mark Salyzyn5392aac2015-05-22 10:03:31 -0700888
889 // do not create any leading drops
890 if (leading) {
891 it = erase(it);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700892 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700893 stats.drop(element);
894 element->setDropped(1);
895 if (last.coalesce(element, 1)) {
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700896 it = erase(it, true);
Mark Salyzyn5392aac2015-05-22 10:03:31 -0700897 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700898 last.add(element);
899 if (worstPid && (!gc
900 || (mLastWorstPidOfSystem[id].find(worstPid)
901 == mLastWorstPidOfSystem[id].end()))) {
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700902 // element->getUid() may not be AID_SYSTEM, next best
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700903 // watermark if current one empty. id is not
904 // LOG_ID_EVENTS or LOG_ID_SECURITY because of worstPid.
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700905 mLastWorstPidOfSystem[id][worstPid] = it;
906 }
Mark Salyzyn6a066942016-07-14 15:34:30 -0700907 if ((!gc && !worstPid) ||
908 (mLastWorst[id].find(worst) == mLastWorst[id].end())) {
909 mLastWorst[id][worst] = it;
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700910 }
Mark Salyzyn5392aac2015-05-22 10:03:31 -0700911 ++it;
912 }
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700913 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700914 if (worst_sizes < second_worst_sizes) {
915 break;
916 }
917 worst_sizes -= len;
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800918 }
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700919 last.clear();
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800920
Mark Salyzyn1c950472014-04-01 17:19:47 -0700921 if (!kick || !mPrune.worstUidEnabled()) {
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800922 break; // the following loop will ask bad clients to skip/drop
923 }
924 }
925
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800926 bool whitelist = false;
Mark Salyzyn083b0372015-12-04 10:59:45 -0800927 bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll;
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800928 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
Mark Salyzyn0175b072014-02-26 09:50:16 -0800929 while((pruneRows > 0) && (it != mLogElements.end())) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700930 LogBufferElement *element = *it;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700931
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700932 if (element->getLogId() != id) {
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700933 it++;
934 continue;
935 }
936
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800937 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
938 mLast[id] = it;
939 mLastSet[id] = true;
940 }
941
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700942 if (oldest && (oldest->mStart <= element->getSequence())) {
Mark Salyzync5dc9702015-09-16 15:34:00 -0700943 busy = true;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700944 if (whitelist) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800945 break;
946 }
Mark Salyzyn1c950472014-04-01 17:19:47 -0700947
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700948 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
949 // kick a misbehaving log reader client off the island
950 oldest->release_Locked();
Mark Salyzynb75cce02015-11-30 11:35:56 -0800951 } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
952 oldest->triggerReader_Locked();
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700953 } else {
954 oldest->triggerSkip_Locked(id, pruneRows);
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800955 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700956 break;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800957 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700958
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700959 if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) {
960 // WhiteListed
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700961 whitelist = true;
962 it++;
963 continue;
964 }
965
966 it = erase(it);
967 pruneRows--;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800968 }
969
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700970 // Do not save the whitelist if we are reader range limited
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800971 if (whitelist && (pruneRows > 0)) {
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800972 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800973 while((it != mLogElements.end()) && (pruneRows > 0)) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700974 LogBufferElement *element = *it;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700975
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700976 if (element->getLogId() != id) {
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700977 ++it;
978 continue;
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800979 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700980
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800981 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
982 mLast[id] = it;
983 mLastSet[id] = true;
984 }
985
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700986 if (oldest && (oldest->mStart <= element->getSequence())) {
Mark Salyzync5dc9702015-09-16 15:34:00 -0700987 busy = true;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700988 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
989 // kick a misbehaving log reader client off the island
990 oldest->release_Locked();
Mark Salyzynb75cce02015-11-30 11:35:56 -0800991 } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
992 oldest->triggerReader_Locked();
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700993 } else {
994 oldest->triggerSkip_Locked(id, pruneRows);
995 }
996 break;
997 }
998
999 it = erase(it);
1000 pruneRows--;
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001001 }
1002 }
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001003
Mark Salyzyn0175b072014-02-26 09:50:16 -08001004 LogTimeEntry::unlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001005
1006 return (pruneRows > 0) && busy;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001007}
1008
1009// clear all rows of type "id" from the buffer.
Mark Salyzync5dc9702015-09-16 15:34:00 -07001010bool LogBuffer::clear(log_id_t id, uid_t uid) {
1011 bool busy = true;
1012 // If it takes more than 4 tries (seconds) to clear, then kill reader(s)
1013 for (int retry = 4;;) {
1014 if (retry == 1) { // last pass
1015 // Check if it is still busy after the sleep, we say prune
1016 // one entry, not another clear run, so we are looking for
1017 // the quick side effect of the return value to tell us if
1018 // we have a _blocked_ reader.
1019 pthread_mutex_lock(&mLogElementsLock);
1020 busy = prune(id, 1, uid);
1021 pthread_mutex_unlock(&mLogElementsLock);
1022 // It is still busy, blocked reader(s), lets kill them all!
1023 // otherwise, lets be a good citizen and preserve the slow
1024 // readers and let the clear run (below) deal with determining
1025 // if we are still blocked and return an error code to caller.
1026 if (busy) {
1027 LogTimeEntry::lock();
1028 LastLogTimes::iterator times = mTimes.begin();
1029 while (times != mTimes.end()) {
1030 LogTimeEntry *entry = (*times);
1031 // Killer punch
1032 if (entry->owned_Locked() && entry->isWatching(id)) {
1033 entry->release_Locked();
1034 }
1035 times++;
1036 }
1037 LogTimeEntry::unlock();
1038 }
1039 }
1040 pthread_mutex_lock(&mLogElementsLock);
1041 busy = prune(id, ULONG_MAX, uid);
1042 pthread_mutex_unlock(&mLogElementsLock);
1043 if (!busy || !--retry) {
1044 break;
1045 }
1046 sleep (1); // Let reader(s) catch up after notification
1047 }
1048 return busy;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001049}
1050
1051// get the used space associated with "id".
1052unsigned long LogBuffer::getSizeUsed(log_id_t id) {
1053 pthread_mutex_lock(&mLogElementsLock);
Mark Salyzyn34facab2014-02-06 14:48:50 -08001054 size_t retval = stats.sizes(id);
Mark Salyzyn0175b072014-02-26 09:50:16 -08001055 pthread_mutex_unlock(&mLogElementsLock);
1056 return retval;
1057}
1058
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001059// set the total space allocated to "id"
1060int LogBuffer::setSize(log_id_t id, unsigned long size) {
1061 // Reasonable limits ...
Mark Salyzynf10e2732016-09-27 13:08:23 -07001062 if (!__android_logger_valid_buffer_size(size)) {
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001063 return -1;
1064 }
1065 pthread_mutex_lock(&mLogElementsLock);
1066 log_buffer_size(id) = size;
1067 pthread_mutex_unlock(&mLogElementsLock);
1068 return 0;
1069}
1070
1071// get the total space allocated to "id"
1072unsigned long LogBuffer::getSize(log_id_t id) {
1073 pthread_mutex_lock(&mLogElementsLock);
1074 size_t retval = log_buffer_size(id);
1075 pthread_mutex_unlock(&mLogElementsLock);
1076 return retval;
1077}
1078
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001079uint64_t LogBuffer::flushTo(
Mark Salyzyn8fa88962016-01-26 14:32:35 -08001080 SocketClient *reader, const uint64_t start,
1081 bool privileged, bool security,
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001082 int (*filter)(const LogBufferElement *element, void *arg), void *arg) {
Mark Salyzyn0175b072014-02-26 09:50:16 -08001083 LogBufferElementCollection::iterator it;
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001084 uint64_t max = start;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001085 uid_t uid = reader->getUid();
1086
1087 pthread_mutex_lock(&mLogElementsLock);
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001088
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001089 if (start <= 1) {
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001090 // client wants to start from the beginning
1091 it = mLogElements.begin();
1092 } else {
1093 // Client wants to start from some specified time. Chances are
1094 // we are better off starting from the end of the time sorted list.
1095 for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) {
1096 --it;
1097 LogBufferElement *element = *it;
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001098 if (element->getSequence() <= start) {
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001099 it++;
1100 break;
1101 }
1102 }
1103 }
1104
Mark Salyzynb5b87962017-01-23 14:20:31 -08001105 // Help detect if the valid message before is from the same source so
1106 // we can differentiate chatty filter types.
1107 pid_t lastTid[LOG_ID_MAX] = { 0 };
1108
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001109 for (; it != mLogElements.end(); ++it) {
Mark Salyzyn0175b072014-02-26 09:50:16 -08001110 LogBufferElement *element = *it;
1111
1112 if (!privileged && (element->getUid() != uid)) {
1113 continue;
1114 }
1115
Mark Salyzyn8fa88962016-01-26 14:32:35 -08001116 if (!security && (element->getLogId() == LOG_ID_SECURITY)) {
1117 continue;
1118 }
1119
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001120 if (element->getSequence() <= start) {
Mark Salyzyn0175b072014-02-26 09:50:16 -08001121 continue;
1122 }
1123
1124 // NB: calling out to another object with mLogElementsLock held (safe)
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001125 if (filter) {
1126 int ret = (*filter)(element, arg);
1127 if (ret == false) {
1128 continue;
1129 }
1130 if (ret != true) {
1131 break;
1132 }
Mark Salyzyn0175b072014-02-26 09:50:16 -08001133 }
1134
Mark Salyzynb5b87962017-01-23 14:20:31 -08001135 bool sameTid = lastTid[element->getLogId()] == element->getTid();
1136 // Dropped (chatty) immediately following a valid log from the
1137 // same source in the same log buffer indicates we have a
1138 // multiple identical squash. chatty that differs source
1139 // is due to spam filter. chatty to chatty of different
1140 // source is also due to spam filter.
1141 lastTid[element->getLogId()] = (element->getDropped() && !sameTid) ?
1142 0 : element->getTid();
1143
Mark Salyzyn0175b072014-02-26 09:50:16 -08001144 pthread_mutex_unlock(&mLogElementsLock);
1145
1146 // range locking in LastLogTimes looks after us
Mark Salyzynb5b87962017-01-23 14:20:31 -08001147 max = element->flushTo(reader, this, privileged, sameTid);
Mark Salyzyn0175b072014-02-26 09:50:16 -08001148
1149 if (max == element->FLUSH_ERROR) {
1150 return max;
1151 }
1152
1153 pthread_mutex_lock(&mLogElementsLock);
1154 }
1155 pthread_mutex_unlock(&mLogElementsLock);
1156
1157 return max;
1158}
Mark Salyzyn34facab2014-02-06 14:48:50 -08001159
Mark Salyzynee3b8382015-12-17 09:58:43 -08001160std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid,
1161 unsigned int logMask) {
Mark Salyzyn34facab2014-02-06 14:48:50 -08001162 pthread_mutex_lock(&mLogElementsLock);
1163
Mark Salyzynee3b8382015-12-17 09:58:43 -08001164 std::string ret = stats.format(uid, pid, logMask);
Mark Salyzyn34facab2014-02-06 14:48:50 -08001165
1166 pthread_mutex_unlock(&mLogElementsLock);
Mark Salyzyn73160ac2015-08-20 10:01:44 -07001167
1168 return ret;
Mark Salyzyn34facab2014-02-06 14:48:50 -08001169}