blob: 9cbc7c41a79f00582cddc2ead2a684990d406272 [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 Salyzyn58363792017-04-17 12:46:12 -070046const log_time LogBuffer::pruneMargin(3, 0);
47
Mark Salyzyn11e55cb2015-03-10 16:45:17 -070048void LogBuffer::init() {
Mark Salyzyndfa7a072014-02-11 12:29:31 -080049 log_id_for_each(i) {
Mark Salyzyn507eb9f2016-01-11 10:58:09 -080050 mLastSet[i] = false;
51 mLast[i] = mLogElements.begin();
52
Mark Salyzynf10e2732016-09-27 13:08:23 -070053 if (setSize(i, __android_logger_get_buffer_size(i))) {
Mark Salyzyn57a0af92014-05-09 17:44:18 -070054 setSize(i, LOG_BUFFER_MIN_SIZE);
55 }
Mark Salyzyndfa7a072014-02-11 12:29:31 -080056 }
Mark Salyzynb6bee332015-09-08 08:56:32 -070057 bool lastMonotonic = monotonic;
Mark Salyzynba7a9a02015-12-01 15:57:25 -080058 monotonic = android_log_clockid() == CLOCK_MONOTONIC;
Mark Salyzynb75cce02015-11-30 11:35:56 -080059 if (lastMonotonic != monotonic) {
60 //
61 // Fixup all timestamps, may not be 100% accurate, but better than
62 // throwing what we have away when we get 'surprised' by a change.
63 // In-place element fixup so no need to check reader-lock. Entries
64 // should already be in timestamp order, but we could end up with a
65 // few out-of-order entries if new monotonics come in before we
66 // are notified of the reinit change in status. A Typical example would
67 // be:
68 // --------- beginning of system
69 // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
70 // --------- beginning of kernel
71 // 0.000000 0 0 I : Initializing cgroup subsys
72 // as the act of mounting /data would trigger persist.logd.timestamp to
73 // be corrected. 1/30 corner case YMMV.
74 //
Mark Salyzyn3c501b52017-04-18 14:09:45 -070075 rdlock();
Mark Salyzynb75cce02015-11-30 11:35:56 -080076 LogBufferElementCollection::iterator it = mLogElements.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -080077 while ((it != mLogElements.end())) {
78 LogBufferElement* e = *it;
Mark Salyzynb75cce02015-11-30 11:35:56 -080079 if (monotonic) {
80 if (!android::isMonotonic(e->mRealTime)) {
81 LogKlog::convertRealToMonotonic(e->mRealTime);
Mark Salyzyn206ed8e2017-05-18 10:06:00 -070082 if ((e->mRealTime.tv_nsec % 1000) == 0) {
83 e->mRealTime.tv_nsec++;
84 }
Mark Salyzynb75cce02015-11-30 11:35:56 -080085 }
86 } else {
87 if (android::isMonotonic(e->mRealTime)) {
88 LogKlog::convertMonotonicToReal(e->mRealTime);
Mark Salyzyn206ed8e2017-05-18 10:06:00 -070089 if ((e->mRealTime.tv_nsec % 1000) == 0) {
90 e->mRealTime.tv_nsec++;
91 }
Mark Salyzynb75cce02015-11-30 11:35:56 -080092 }
93 }
94 ++it;
95 }
Mark Salyzyn3c501b52017-04-18 14:09:45 -070096 unlock();
Mark Salyzynb6bee332015-09-08 08:56:32 -070097 }
98
Mark Salyzynb75cce02015-11-30 11:35:56 -080099 // We may have been triggered by a SIGHUP. Release any sleeping reader
100 // threads to dump their current content.
Mark Salyzynb6bee332015-09-08 08:56:32 -0700101 //
Mark Salyzynb75cce02015-11-30 11:35:56 -0800102 // NB: this is _not_ performed in the context of a SIGHUP, it is
103 // performed during startup, and in context of reinit administrative thread
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700104 LogTimeEntry::wrlock();
Mark Salyzynb75cce02015-11-30 11:35:56 -0800105
106 LastLogTimes::iterator times = mTimes.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -0800107 while (times != mTimes.end()) {
Tom Cherry4f227862018-10-08 17:33:50 -0700108 LogTimeEntry* entry = times->get();
109 entry->triggerReader_Locked();
Mark Salyzynb75cce02015-11-30 11:35:56 -0800110 times++;
Mark Salyzynb6bee332015-09-08 08:56:32 -0700111 }
Mark Salyzynb75cce02015-11-30 11:35:56 -0800112
113 LogTimeEntry::unlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -0800114}
115
Mark Salyzyn501c3732017-03-10 14:31:54 -0800116LogBuffer::LogBuffer(LastLogTimes* times)
117 : monotonic(android_log_clockid() == CLOCK_MONOTONIC), mTimes(*times) {
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700118 pthread_rwlock_init(&mLogElementsLock, nullptr);
Mark Salyzyn11e55cb2015-03-10 16:45:17 -0700119
Mark Salyzyna2c02222016-12-13 10:31:29 -0800120 log_id_for_each(i) {
Mark Salyzynae2abf12017-03-31 10:48:39 -0700121 lastLoggedElements[i] = nullptr;
122 droppedElements[i] = nullptr;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800123 }
124
Mark Salyzyn11e55cb2015-03-10 16:45:17 -0700125 init();
126}
127
Mark Salyzyna2c02222016-12-13 10:31:29 -0800128LogBuffer::~LogBuffer() {
129 log_id_for_each(i) {
130 delete lastLoggedElements[i];
131 delete droppedElements[i];
132 }
133}
134
Mark Salyzyn501c3732017-03-10 14:31:54 -0800135enum match_type { DIFFERENT, SAME, SAME_LIBLOG };
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800136
Mark Salyzyn501c3732017-03-10 14:31:54 -0800137static enum match_type identical(LogBufferElement* elem,
138 LogBufferElement* last) {
Mark Salyzyna2c02222016-12-13 10:31:29 -0800139 // is it mostly identical?
Mark Salyzyn501c3732017-03-10 14:31:54 -0800140 // if (!elem) return DIFFERENT;
Mark Salyzyn0484b3b2016-08-11 08:02:06 -0700141 ssize_t lenl = elem->getMsgLen();
142 if (lenl <= 0) return DIFFERENT; // value if this represents a chatty elem
Mark Salyzyn501c3732017-03-10 14:31:54 -0800143 // if (!last) return DIFFERENT;
Mark Salyzyn0484b3b2016-08-11 08:02:06 -0700144 ssize_t lenr = last->getMsgLen();
145 if (lenr <= 0) return DIFFERENT; // value if this represents a chatty elem
Mark Salyzyn501c3732017-03-10 14:31:54 -0800146 // if (elem->getLogId() != last->getLogId()) return DIFFERENT;
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800147 if (elem->getUid() != last->getUid()) return DIFFERENT;
148 if (elem->getPid() != last->getPid()) return DIFFERENT;
149 if (elem->getTid() != last->getTid()) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800150
151 // last is more than a minute old, stop squashing identical messages
152 if (elem->getRealTime().nsec() >
Mark Salyzyn501c3732017-03-10 14:31:54 -0800153 (last->getRealTime().nsec() + 60 * NS_PER_SEC))
154 return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800155
156 // Identical message
157 const char* msgl = elem->getMsg();
158 const char* msgr = last->getMsg();
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800159 if (lenl == lenr) {
160 if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME;
161 // liblog tagged messages (content gets summed)
162 if ((elem->getLogId() == LOG_ID_EVENTS) &&
163 (lenl == sizeof(android_log_event_int_t)) &&
Mark Salyzyn501c3732017-03-10 14:31:54 -0800164 !fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_int_t) -
165 sizeof(int32_t)) &&
Mark Salyzyn1598fe02017-03-13 15:41:59 -0700166 (elem->getTag() == LIBLOG_LOG_TAG)) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800167 return SAME_LIBLOG;
Mark Salyzyn1598fe02017-03-13 15:41:59 -0700168 }
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800169 }
Mark Salyzyna2c02222016-12-13 10:31:29 -0800170
171 // audit message (except sequence number) identical?
Mark Salyzynfec2e2c2018-03-13 11:06:38 -0700172 if (last->isBinary() &&
173 (lenl > static_cast<ssize_t>(sizeof(android_log_event_string_t))) &&
174 (lenr > static_cast<ssize_t>(sizeof(android_log_event_string_t)))) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800175 if (fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_string_t) -
Mark Salyzyn1598fe02017-03-13 15:41:59 -0700176 sizeof(int32_t))) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800177 return DIFFERENT;
Mark Salyzyn1598fe02017-03-13 15:41:59 -0700178 }
Mark Salyzyna2c02222016-12-13 10:31:29 -0800179 msgl += sizeof(android_log_event_string_t);
180 lenl -= sizeof(android_log_event_string_t);
181 msgr += sizeof(android_log_event_string_t);
182 lenr -= sizeof(android_log_event_string_t);
183 }
Mark Salyzyn0484b3b2016-08-11 08:02:06 -0700184 static const char avc[] = "): avc: ";
Mark Salyzyn501c3732017-03-10 14:31:54 -0800185 const char* avcl = android::strnstr(msgl, lenl, avc);
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800186 if (!avcl) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800187 lenl -= avcl - msgl;
Mark Salyzyn501c3732017-03-10 14:31:54 -0800188 const char* avcr = android::strnstr(msgr, lenr, avc);
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800189 if (!avcr) return DIFFERENT;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800190 lenr -= avcr - msgr;
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800191 if (lenl != lenr) return DIFFERENT;
Mark Salyzyn0484b3b2016-08-11 08:02:06 -0700192 if (fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc),
Mark Salyzyn1598fe02017-03-13 15:41:59 -0700193 lenl - strlen(avc))) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800194 return DIFFERENT;
Mark Salyzyn1598fe02017-03-13 15:41:59 -0700195 }
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800196 return SAME;
Mark Salyzyna2c02222016-12-13 10:31:29 -0800197}
198
Mark Salyzyn501c3732017-03-10 14:31:54 -0800199int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
Chih-Hung Hsieh08d470b2018-08-13 14:22:56 -0700200 pid_t tid, const char* msg, uint16_t len) {
Yi Kong141ccee2018-03-01 17:48:53 -0500201 if (log_id >= LOG_ID_MAX) {
Mark Salyzyn202e1532015-02-09 08:21:05 -0800202 return -EINVAL;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800203 }
Mark Salyzyne59c4692014-10-02 13:07:05 -0700204
Mark Salyzyn206ed8e2017-05-18 10:06:00 -0700205 // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns.
206 // This prevents any chance that an outside source can request an
207 // exact entry with time specified in ms or us precision.
208 if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec;
209
Mark Salyzyn501c3732017-03-10 14:31:54 -0800210 LogBufferElement* elem =
211 new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len);
Mark Salyzyn0ee8de32016-01-06 21:17:43 +0000212 if (log_id != LOG_ID_SECURITY) {
Mark Salyzyn083b0372015-12-04 10:59:45 -0800213 int prio = ANDROID_LOG_INFO;
Mark Salyzynae2abf12017-03-31 10:48:39 -0700214 const char* tag = nullptr;
Paul Elliottc6ed8f32017-11-07 11:11:41 +0000215 size_t tag_len = 0;
Yao Chen025f05a2017-12-01 15:48:19 -0800216 if (log_id == LOG_ID_EVENTS || log_id == LOG_ID_STATS) {
Mark Salyzyn61e9ce62016-09-12 14:51:54 -0700217 tag = tagToName(elem->getTag());
Paul Elliottc6ed8f32017-11-07 11:11:41 +0000218 if (tag) {
219 tag_len = strlen(tag);
220 }
Mark Salyzyn083b0372015-12-04 10:59:45 -0800221 } else {
222 prio = *msg;
223 tag = msg + 1;
Paul Elliottc6ed8f32017-11-07 11:11:41 +0000224 tag_len = strnlen(tag, len - 1);
Mark Salyzyn083b0372015-12-04 10:59:45 -0800225 }
Paul Elliottc6ed8f32017-11-07 11:11:41 +0000226 if (!__android_log_is_loggable_len(prio, tag, tag_len,
227 ANDROID_LOG_VERBOSE)) {
Mark Salyzyn083b0372015-12-04 10:59:45 -0800228 // Log traffic received to total
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700229 wrlock();
Mark Salyzyn02dd2f42017-04-14 09:46:57 -0700230 stats.addTotal(elem);
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700231 unlock();
Mark Salyzyn083b0372015-12-04 10:59:45 -0800232 delete elem;
233 return -EACCES;
234 }
Mark Salyzyne59c4692014-10-02 13:07:05 -0700235 }
Mark Salyzyn0175b072014-02-26 09:50:16 -0800236
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700237 wrlock();
Mark Salyzyna2c02222016-12-13 10:31:29 -0800238 LogBufferElement* currentLast = lastLoggedElements[log_id];
239 if (currentLast) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800240 LogBufferElement* dropped = droppedElements[log_id];
Chih-Hung Hsieh08d470b2018-08-13 14:22:56 -0700241 uint16_t count = dropped ? dropped->getDropped() : 0;
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800242 //
243 // State Init
244 // incoming:
Mark Salyzynae2abf12017-03-31 10:48:39 -0700245 // dropped = nullptr
246 // currentLast = nullptr;
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800247 // elem = incoming message
248 // outgoing:
Mark Salyzynae2abf12017-03-31 10:48:39 -0700249 // dropped = nullptr -> State 0
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800250 // currentLast = copy of elem
251 // log elem
252 // State 0
253 // incoming:
254 // count = 0
Mark Salyzynae2abf12017-03-31 10:48:39 -0700255 // dropped = nullptr
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800256 // currentLast = copy of last message
257 // elem = incoming message
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800258 // outgoing: if match != DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800259 // dropped = copy of first identical message -> State 1
260 // currentLast = reference to elem
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800261 // break: if match == DIFFERENT
Mark Salyzynae2abf12017-03-31 10:48:39 -0700262 // dropped = nullptr -> State 0
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800263 // delete copy of last message (incoming currentLast)
264 // currentLast = copy of elem
265 // log elem
266 // State 1
267 // incoming:
268 // count = 0
269 // dropped = copy of first identical message
270 // currentLast = reference to last held-back incoming
271 // message
272 // elem = incoming message
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800273 // outgoing: if match == SAME
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800274 // delete copy of first identical message (dropped)
275 // dropped = reference to last held-back incoming
276 // message set to chatty count of 1 -> State 2
277 // currentLast = reference to elem
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800278 // outgoing: if match == SAME_LIBLOG
279 // dropped = copy of first identical message -> State 1
280 // take sum of currentLast and elem
281 // if sum overflows:
282 // log currentLast
283 // currentLast = reference to elem
284 // else
285 // delete currentLast
286 // currentLast = reference to elem, sum liblog.
287 // break: if match == DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800288 // delete dropped
Mark Salyzynae2abf12017-03-31 10:48:39 -0700289 // dropped = nullptr -> State 0
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800290 // log reference to last held-back (currentLast)
291 // currentLast = copy of elem
292 // log elem
293 // State 2
294 // incoming:
295 // count = chatty count
296 // dropped = chatty message holding count
297 // currentLast = reference to last held-back incoming
298 // message.
299 // dropped = chatty message holding count
300 // elem = incoming message
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800301 // outgoing: if match != DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800302 // delete chatty message holding count
303 // dropped = reference to last held-back incoming
304 // message, set to chatty count + 1
305 // currentLast = reference to elem
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800306 // break: if match == DIFFERENT
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800307 // log dropped (chatty message)
Mark Salyzynae2abf12017-03-31 10:48:39 -0700308 // dropped = nullptr -> State 0
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800309 // log reference to last held-back (currentLast)
310 // currentLast = copy of elem
311 // log elem
312 //
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800313 enum match_type match = identical(elem, currentLast);
314 if (match != DIFFERENT) {
Mark Salyzyna2c02222016-12-13 10:31:29 -0800315 if (dropped) {
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800316 // Sum up liblog tag messages?
317 if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) {
318 android_log_event_int_t* event =
319 reinterpret_cast<android_log_event_int_t*>(
320 const_cast<char*>(currentLast->getMsg()));
321 //
322 // To unit test, differentiate with something like:
323 // event->header.tag = htole32(CHATTY_LOG_TAG);
324 // here, then instead of delete currentLast below,
325 // log(currentLast) to see the incremental sums form.
326 //
327 uint32_t swab = event->payload.data;
328 unsigned long long total = htole32(swab);
329 event = reinterpret_cast<android_log_event_int_t*>(
Mark Salyzyn501c3732017-03-10 14:31:54 -0800330 const_cast<char*>(elem->getMsg()));
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800331 swab = event->payload.data;
332
333 lastLoggedElements[LOG_ID_EVENTS] = elem;
334 total += htole32(swab);
335 // check for overflow
336 if (total >= UINT32_MAX) {
337 log(currentLast);
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700338 unlock();
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800339 return len;
340 }
Mark Salyzyn02dd2f42017-04-14 09:46:57 -0700341 stats.addTotal(currentLast);
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800342 delete currentLast;
343 swab = total;
344 event->payload.data = htole32(swab);
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700345 unlock();
Mark Salyzyn1dfb4de2016-12-16 16:09:15 -0800346 return len;
347 }
Mark Salyzyna2c02222016-12-13 10:31:29 -0800348 if (count == USHRT_MAX) {
349 log(dropped);
350 count = 1;
351 } else {
352 delete dropped;
353 ++count;
354 }
355 }
356 if (count) {
Mark Salyzyn02dd2f42017-04-14 09:46:57 -0700357 stats.addTotal(currentLast);
Mark Salyzyna2c02222016-12-13 10:31:29 -0800358 currentLast->setDropped(count);
359 }
360 droppedElements[log_id] = currentLast;
361 lastLoggedElements[log_id] = elem;
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700362 unlock();
Mark Salyzyna2c02222016-12-13 10:31:29 -0800363 return len;
364 }
Mark Salyzyn501c3732017-03-10 14:31:54 -0800365 if (dropped) { // State 1 or 2
366 if (count) { // State 2
367 log(dropped); // report chatty
368 } else { // State 1
369 delete dropped;
Mark Salyzyn8f83a352016-12-16 16:09:15 -0800370 }
Mark Salyzynae2abf12017-03-31 10:48:39 -0700371 droppedElements[log_id] = nullptr;
Mark Salyzyn501c3732017-03-10 14:31:54 -0800372 log(currentLast); // report last message in the series
373 } else { // State 0
Mark Salyzyna2c02222016-12-13 10:31:29 -0800374 delete currentLast;
375 }
376 }
377 lastLoggedElements[log_id] = new LogBufferElement(*elem);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800378
Mark Salyzyna2c02222016-12-13 10:31:29 -0800379 log(elem);
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700380 unlock();
Mark Salyzyna2c02222016-12-13 10:31:29 -0800381
382 return len;
383}
384
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700385// assumes LogBuffer::wrlock() held, owns elem, look after garbage collection
Mark Salyzyna2c02222016-12-13 10:31:29 -0800386void LogBuffer::log(LogBufferElement* elem) {
Mark Salyzyn09d66322017-03-14 13:11:12 -0700387 // cap on how far back we will sort in-place, otherwise append
388 static uint32_t too_far_back = 5; // five seconds
Mark Salyzyn0175b072014-02-26 09:50:16 -0800389 // Insert elements in time sorted order if possible
390 // NB: if end is region locked, place element at end of list
391 LogBufferElementCollection::iterator it = mLogElements.end();
392 LogBufferElementCollection::iterator last = it;
Mark Salyzyn1d84f0b2017-03-03 10:21:23 -0800393 if (__predict_true(it != mLogElements.begin())) --it;
394 if (__predict_false(it == mLogElements.begin()) ||
Mark Salyzyn09d66322017-03-14 13:11:12 -0700395 __predict_true((*it)->getRealTime() <= elem->getRealTime()) ||
396 __predict_false((((*it)->getRealTime().tv_sec - too_far_back) >
397 elem->getRealTime().tv_sec) &&
398 (elem->getLogId() != LOG_ID_KERNEL) &&
399 ((*it)->getLogId() != LOG_ID_KERNEL))) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800400 mLogElements.push_back(elem);
401 } else {
Bernie Innocenti804e7d82019-01-16 15:25:18 +0900402 log_time end(log_time::EPOCH);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800403 bool end_set = false;
404 bool end_always = false;
405
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700406 LogTimeEntry::rdlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -0800407
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700408 LastLogTimes::iterator times = mTimes.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -0800409 while (times != mTimes.end()) {
Tom Cherry4f227862018-10-08 17:33:50 -0700410 LogTimeEntry* entry = times->get();
411 if (!entry->mNonBlock) {
412 end_always = true;
413 break;
414 }
415 // it passing mEnd is blocked by the following checks.
416 if (!end_set || (end <= entry->mEnd)) {
417 end = entry->mEnd;
418 end_set = true;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800419 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700420 times++;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800421 }
422
Mark Salyzyn5a34d6e2017-03-10 08:44:14 -0800423 if (end_always || (end_set && (end > (*it)->getRealTime()))) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800424 mLogElements.push_back(elem);
425 } else {
Mark Salyzyn1d84f0b2017-03-03 10:21:23 -0800426 // should be short as timestamps are localized near end()
427 do {
428 last = it;
429 if (__predict_false(it == mLogElements.begin())) {
430 break;
431 }
Mark Salyzyn1d84f0b2017-03-03 10:21:23 -0800432 --it;
433 } while (((*it)->getRealTime() > elem->getRealTime()) &&
Mark Salyzyn5a34d6e2017-03-10 08:44:14 -0800434 (!end_set || (end <= (*it)->getRealTime())));
Mark Salyzyna2c02222016-12-13 10:31:29 -0800435 mLogElements.insert(last, elem);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800436 }
Mark Salyzyn0175b072014-02-26 09:50:16 -0800437 LogTimeEntry::unlock();
438 }
439
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700440 stats.add(elem);
Mark Salyzyna2c02222016-12-13 10:31:29 -0800441 maybePrune(elem->getLogId());
Mark Salyzyn0175b072014-02-26 09:50:16 -0800442}
443
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700444// Prune at most 10% of the log entries or maxPrune, whichever is less.
Mark Salyzyn0175b072014-02-26 09:50:16 -0800445//
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700446// LogBuffer::wrlock() must be held when this function is called.
Mark Salyzyn0175b072014-02-26 09:50:16 -0800447void LogBuffer::maybePrune(log_id_t id) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800448 size_t sizes = stats.sizes(id);
Mark Salyzyn62ab0fd2015-08-10 10:23:56 -0700449 unsigned long maxSize = log_buffer_size(id);
450 if (sizes > maxSize) {
Mark Salyzynb39ed0c2015-08-19 12:20:36 -0700451 size_t sizeOver = sizes - ((maxSize * 9) / 10);
Mark Salyzyn58b8be82015-09-30 07:40:09 -0700452 size_t elements = stats.realElements(id);
453 size_t minElements = elements / 100;
454 if (minElements < minPrune) {
455 minElements = minPrune;
456 }
Mark Salyzyn62ab0fd2015-08-10 10:23:56 -0700457 unsigned long pruneRows = elements * sizeOver / sizes;
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700458 if (pruneRows < minElements) {
Mark Salyzyn62ab0fd2015-08-10 10:23:56 -0700459 pruneRows = minElements;
Mark Salyzyn740f9b42014-01-13 16:37:51 -0800460 }
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700461 if (pruneRows > maxPrune) {
462 pruneRows = maxPrune;
Mark Salyzynb39ed0c2015-08-19 12:20:36 -0700463 }
Mark Salyzyn740f9b42014-01-13 16:37:51 -0800464 prune(id, pruneRows);
Mark Salyzyn0175b072014-02-26 09:50:16 -0800465 }
466}
467
Mark Salyzyn831aa292015-09-03 16:08:50 -0700468LogBufferElementCollection::iterator LogBuffer::erase(
Mark Salyzyn501c3732017-03-10 14:31:54 -0800469 LogBufferElementCollection::iterator it, bool coalesce) {
470 LogBufferElement* element = *it;
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700471 log_id_t id = element->getLogId();
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700472
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700473 // Remove iterator references in the various lists that will become stale
474 // after the element is erased from the main logging list.
475
Mark Salyzyn501c3732017-03-10 14:31:54 -0800476 { // start of scope for found iterator
477 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY))
478 ? element->getTag()
479 : element->getUid();
Mark Salyzyn6a066942016-07-14 15:34:30 -0700480 LogBufferIteratorMap::iterator found = mLastWorst[id].find(key);
481 if ((found != mLastWorst[id].end()) && (it == found->second)) {
482 mLastWorst[id].erase(found);
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700483 }
Mark Salyzync892ea32015-08-19 17:06:11 -0700484 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700485
Mark Salyzyn501c3732017-03-10 14:31:54 -0800486 { // start of scope for pid found iterator
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700487 // element->getUid() may not be AID_SYSTEM for next-best-watermark.
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700488 // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and
489 // long term code stability, find() check should be fast for those ids.
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700490 LogBufferPidIteratorMap::iterator found =
491 mLastWorstPidOfSystem[id].find(element->getPid());
Mark Salyzyn501c3732017-03-10 14:31:54 -0800492 if ((found != mLastWorstPidOfSystem[id].end()) &&
493 (it == found->second)) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700494 mLastWorstPidOfSystem[id].erase(found);
495 }
496 }
497
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800498 bool setLast[LOG_ID_MAX];
499 bool doSetLast = false;
500 log_id_for_each(i) {
501 doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]);
502 }
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700503#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
504 LogBufferElementCollection::iterator bad = it;
Mark Salyzyn501c3732017-03-10 14:31:54 -0800505 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY))
506 ? element->getTag()
507 : element->getUid();
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700508#endif
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700509 it = mLogElements.erase(it);
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800510 if (doSetLast) {
511 log_id_for_each(i) {
512 if (setLast[i]) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800513 if (__predict_false(it == mLogElements.end())) { // impossible
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800514 mLastSet[i] = false;
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700515 mLast[i] = mLogElements.begin();
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800516 } else {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800517 mLast[i] = it; // push down the road as next-best-watermark
Mark Salyzyn7fd6c5c2016-01-19 16:04:41 -0800518 }
519 }
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800520 }
521 }
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700522#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
523 log_id_for_each(i) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800524 for (auto b : mLastWorst[i]) {
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700525 if (bad == b.second) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800526 android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i,
527 b.first, key);
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700528 }
529 }
Mark Salyzyn501c3732017-03-10 14:31:54 -0800530 for (auto b : mLastWorstPidOfSystem[i]) {
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700531 if (bad == b.second) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800532 android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i,
533 b.first);
Mark Salyzyn60636fa2016-10-24 16:22:17 -0700534 }
535 }
536 if (mLastSet[i] && (bad == mLast[i])) {
537 android::prdebug("stale mLast[%d]\n", i);
538 mLastSet[i] = false;
539 mLast[i] = mLogElements.begin();
540 }
541 }
542#endif
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700543 if (coalesce) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700544 stats.erase(element);
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700545 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700546 stats.subtract(element);
Mark Salyzyn831aa292015-09-03 16:08:50 -0700547 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700548 delete element;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700549
550 return it;
551}
552
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700553// Define a temporary mechanism to report the last LogBufferElement pointer
554// for the specified uid, pid and tid. Used below to help merge-sort when
555// pruning for worst UID.
556class LogBufferElementKey {
557 const union {
558 struct {
Mark Salyzyn684bdb52016-12-13 12:44:20 -0800559 uint32_t uid;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700560 uint16_t pid;
561 uint16_t tid;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700562 } __packed;
563 uint64_t value;
564 } __packed;
565
Mark Salyzyn501c3732017-03-10 14:31:54 -0800566 public:
567 LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid)
568 : uid(uid), pid(pid), tid(tid) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700569 }
Mark Salyzyn501c3732017-03-10 14:31:54 -0800570 explicit LogBufferElementKey(uint64_t key) : value(key) {
571 }
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700572
Mark Salyzyn501c3732017-03-10 14:31:54 -0800573 uint64_t getKey() {
574 return value;
575 }
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700576};
577
Mark Salyzyn511338d2015-05-19 09:12:30 -0700578class LogBufferElementLast {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800579 typedef std::unordered_map<uint64_t, LogBufferElement*> LogBufferElementMap;
Mark Salyzyn511338d2015-05-19 09:12:30 -0700580 LogBufferElementMap map;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700581
Mark Salyzyn501c3732017-03-10 14:31:54 -0800582 public:
Chih-Hung Hsieh08d470b2018-08-13 14:22:56 -0700583 bool coalesce(LogBufferElement* element, uint16_t dropped) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800584 LogBufferElementKey key(element->getUid(), element->getPid(),
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700585 element->getTid());
Mark Salyzyn511338d2015-05-19 09:12:30 -0700586 LogBufferElementMap::iterator it = map.find(key.getKey());
587 if (it != map.end()) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800588 LogBufferElement* found = it->second;
Chih-Hung Hsieh08d470b2018-08-13 14:22:56 -0700589 uint16_t moreDropped = found->getDropped();
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700590 if ((dropped + moreDropped) > USHRT_MAX) {
Mark Salyzyn511338d2015-05-19 09:12:30 -0700591 map.erase(it);
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700592 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700593 found->setDropped(dropped + moreDropped);
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700594 return true;
595 }
596 }
597 return false;
598 }
599
Mark Salyzyn501c3732017-03-10 14:31:54 -0800600 void add(LogBufferElement* element) {
601 LogBufferElementKey key(element->getUid(), element->getPid(),
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700602 element->getTid());
603 map[key.getKey()] = element;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700604 }
605
Mark Salyzyne06a6e02015-04-20 14:08:56 -0700606 inline void clear() {
Mark Salyzyn511338d2015-05-19 09:12:30 -0700607 map.clear();
Mark Salyzyne06a6e02015-04-20 14:08:56 -0700608 }
609
Mark Salyzyn501c3732017-03-10 14:31:54 -0800610 void clear(LogBufferElement* element) {
Mark Salyzyn5a34d6e2017-03-10 08:44:14 -0800611 log_time current =
612 element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0);
Mark Salyzyn501c3732017-03-10 14:31:54 -0800613 for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
614 LogBufferElement* mapElement = it->second;
615 if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) &&
Mark Salyzyn5a34d6e2017-03-10 08:44:14 -0800616 (current > mapElement->getRealTime())) {
Mark Salyzyn511338d2015-05-19 09:12:30 -0700617 it = map.erase(it);
618 } else {
619 ++it;
Mark Salyzyne06a6e02015-04-20 14:08:56 -0700620 }
621 }
622 }
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700623};
624
Mark Salyzyn0878a7c2017-05-11 13:28:33 -0700625// Determine if watermark is within pruneMargin + 1s from the end of the list,
626// the caller will use this result to set an internal busy flag indicating
627// the prune operation could not be completed because a reader is blocking
628// the request.
629bool LogBuffer::isBusy(log_time watermark) {
630 LogBufferElementCollection::iterator ei = mLogElements.end();
631 --ei;
632 return watermark < ((*ei)->getRealTime() - pruneMargin - log_time(1, 0));
633}
634
635// If the selected reader is blocking our pruning progress, decide on
636// what kind of mitigation is necessary to unblock the situation.
637void LogBuffer::kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows) {
638 if (stats.sizes(id) > (2 * log_buffer_size(id))) { // +100%
639 // A misbehaving or slow reader has its connection
640 // dropped if we hit too much memory pressure.
641 me->release_Locked();
642 } else if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
643 // Allow a blocked WRAP timeout reader to
644 // trigger and start reporting the log data.
645 me->triggerReader_Locked();
646 } else {
647 // tell slow reader to skip entries to catch up
648 me->triggerSkip_Locked(id, pruneRows);
649 }
650}
651
Mark Salyzyn0175b072014-02-26 09:50:16 -0800652// prune "pruneRows" of type "id" from the buffer.
653//
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700654// This garbage collection task is used to expire log entries. It is called to
655// remove all logs (clear), all UID logs (unprivileged clear), or every
656// 256 or 10% of the total logs (whichever is less) to prune the logs.
657//
658// First there is a prep phase where we discover the reader region lock that
659// acts as a backstop to any pruning activity to stop there and go no further.
660//
661// There are three major pruning loops that follow. All expire from the oldest
662// entries. Since there are multiple log buffers, the Android logging facility
663// will appear to drop entries 'in the middle' when looking at multiple log
664// sources and buffers. This effect is slightly more prominent when we prune
665// the worst offender by logging source. Thus the logs slowly loose content
666// and value as you move back in time. This is preferred since chatty sources
667// invariably move the logs value down faster as less chatty sources would be
668// expired in the noise.
669//
670// The first loop performs blacklisting and worst offender pruning. Falling
671// through when there are no notable worst offenders and have not hit the
672// region lock preventing further worst offender pruning. This loop also looks
673// after managing the chatty log entries and merging to help provide
674// statistical basis for blame. The chatty entries are not a notification of
675// how much logs you may have, but instead represent how much logs you would
676// have had in a virtual log buffer that is extended to cover all the in-memory
677// logs without loss. They last much longer than the represented pruned logs
678// since they get multiplied by the gains in the non-chatty log sources.
679//
680// The second loop get complicated because an algorithm of watermarks and
681// history is maintained to reduce the order and keep processing time
682// down to a minimum at scale. These algorithms can be costly in the face
683// of larger log buffers, or severly limited processing time granted to a
684// background task at lowest priority.
685//
686// This second loop does straight-up expiration from the end of the logs
687// (again, remember for the specified log buffer id) but does some whitelist
688// preservation. Thus whitelist is a Hail Mary low priority, blacklists and
689// spam filtration all take priority. This second loop also checks if a region
690// lock is causing us to buffer too much in the logs to help the reader(s),
691// and will tell the slowest reader thread to skip log entries, and if
692// persistent and hits a further threshold, kill the reader thread.
693//
694// The third thread is optional, and only gets hit if there was a whitelist
695// and more needs to be pruned against the backstop of the region lock.
696//
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700697// LogBuffer::wrlock() must be held when this function is called.
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700698//
Mark Salyzync5dc9702015-09-16 15:34:00 -0700699bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
Mark Salyzynae2abf12017-03-31 10:48:39 -0700700 LogTimeEntry* oldest = nullptr;
Mark Salyzync5dc9702015-09-16 15:34:00 -0700701 bool busy = false;
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700702 bool clearAll = pruneRows == ULONG_MAX;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800703
Mark Salyzyn3c501b52017-04-18 14:09:45 -0700704 LogTimeEntry::rdlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -0800705
706 // Region locked?
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700707 LastLogTimes::iterator times = mTimes.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -0800708 while (times != mTimes.end()) {
Tom Cherry4f227862018-10-08 17:33:50 -0700709 LogTimeEntry* entry = times->get();
710 if (entry->isWatching(id) &&
Mark Salyzyn501c3732017-03-10 14:31:54 -0800711 (!oldest || (oldest->mStart > entry->mStart) ||
712 ((oldest->mStart == entry->mStart) &&
713 (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
Mark Salyzyn0175b072014-02-26 09:50:16 -0800714 oldest = entry;
715 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700716 times++;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800717 }
Mark Salyzyn58363792017-04-17 12:46:12 -0700718 log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max);
719 if (oldest) watermark = oldest->mStart - pruneMargin;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800720
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800721 LogBufferElementCollection::iterator it;
722
Mark Salyzyn501c3732017-03-10 14:31:54 -0800723 if (__predict_false(caller_uid != AID_ROOT)) { // unlikely
Mark Salyzyn43a5f312016-09-01 15:48:36 -0700724 // Only here if clear all request from non system source, so chatty
725 // filter logistics is not required.
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800726 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
727 while (it != mLogElements.end()) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800728 LogBufferElement* element = *it;
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700729
Mark Salyzyn501c3732017-03-10 14:31:54 -0800730 if ((element->getLogId() != id) ||
731 (element->getUid() != caller_uid)) {
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700732 ++it;
733 continue;
734 }
735
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800736 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
737 mLast[id] = it;
738 mLastSet[id] = true;
739 }
740
Mark Salyzyn58363792017-04-17 12:46:12 -0700741 if (oldest && (watermark <= element->getRealTime())) {
Mark Salyzyn0878a7c2017-05-11 13:28:33 -0700742 busy = isBusy(watermark);
743 if (busy) kickMe(oldest, id, pruneRows);
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700744 break;
745 }
746
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700747 it = erase(it);
Mark Salyzyn43a5f312016-09-01 15:48:36 -0700748 if (--pruneRows == 0) {
749 break;
750 }
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700751 }
752 LogTimeEntry::unlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -0700753 return busy;
Mark Salyzyn1a240b42014-06-12 11:16:16 -0700754 }
755
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700756 // prune by worst offenders; by blacklist, UID, and by PID of system UID
Mark Salyzyn083b0372015-12-04 10:59:45 -0800757 bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty();
Mark Salyzyn2b25c662015-09-16 15:34:00 -0700758 while (!clearAll && (pruneRows > 0)) {
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800759 // recalculate the worst offender on every batched pass
Mark Salyzyn501c3732017-03-10 14:31:54 -0800760 int worst = -1; // not valid for getUid() or getKey()
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800761 size_t worst_sizes = 0;
762 size_t second_worst_sizes = 0;
Mark Salyzyn501c3732017-03-10 14:31:54 -0800763 pid_t worstPid = 0; // POSIX guarantees PID != 0
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800764
Mark Salyzynae769232015-03-17 17:17:25 -0700765 if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) {
Mark Salyzyn6a066942016-07-14 15:34:30 -0700766 // Calculate threshold as 12.5% of available storage
767 size_t threshold = log_buffer_size(id) / 8;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700768
Mark Salyzyn6a066942016-07-14 15:34:30 -0700769 if ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800770 stats.sortTags(AID_ROOT, (pid_t)0, 2, id)
771 .findWorst(worst, worst_sizes, second_worst_sizes,
772 threshold);
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700773 // per-pid filter for AID_SYSTEM sources is too complex
Mark Salyzyn6a066942016-07-14 15:34:30 -0700774 } else {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800775 stats.sort(AID_ROOT, (pid_t)0, 2, id)
776 .findWorst(worst, worst_sizes, second_worst_sizes,
777 threshold);
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700778
Mark Salyzyn6a066942016-07-14 15:34:30 -0700779 if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800780 stats.sortPids(worst, (pid_t)0, 2, id)
781 .findWorst(worstPid, worst_sizes, second_worst_sizes);
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700782 }
783 }
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800784 }
785
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700786 // skip if we have neither worst nor naughty filters
Mark Salyzyn6a066942016-07-14 15:34:30 -0700787 if ((worst == -1) && !hasBlacklist) {
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700788 break;
789 }
790
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800791 bool kick = false;
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700792 bool leading = true;
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800793 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700794 // Perform at least one mandatory garbage collection cycle in following
795 // - clear leading chatty tags
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700796 // - coalesce chatty tags
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700797 // - check age-out of preserved logs
798 bool gc = pruneRows <= 1;
Mark Salyzyn6a066942016-07-14 15:34:30 -0700799 if (!gc && (worst != -1)) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800800 { // begin scope for worst found iterator
801 LogBufferIteratorMap::iterator found =
802 mLastWorst[id].find(worst);
803 if ((found != mLastWorst[id].end()) &&
804 (found->second != mLogElements.end())) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700805 leading = false;
806 it = found->second;
807 }
808 }
Mark Salyzyn501c3732017-03-10 14:31:54 -0800809 if (worstPid) { // begin scope for pid worst found iterator
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700810 // FYI: worstPid only set if !LOG_ID_EVENTS and
811 // !LOG_ID_SECURITY, not going to make that assumption ...
Mark Salyzyn501c3732017-03-10 14:31:54 -0800812 LogBufferPidIteratorMap::iterator found =
813 mLastWorstPidOfSystem[id].find(worstPid);
814 if ((found != mLastWorstPidOfSystem[id].end()) &&
815 (found->second != mLogElements.end())) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700816 leading = false;
817 it = found->second;
818 }
Mark Salyzync892ea32015-08-19 17:06:11 -0700819 }
820 }
Mark Salyzyn501c3732017-03-10 14:31:54 -0800821 static const timespec too_old = { EXPIRE_HOUR_THRESHOLD * 60 * 60, 0 };
Mark Salyzynccfe8442015-08-24 13:43:27 -0700822 LogBufferElementCollection::iterator lastt;
823 lastt = mLogElements.end();
824 --lastt;
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700825 LogBufferElementLast last;
Mark Salyzync892ea32015-08-19 17:06:11 -0700826 while (it != mLogElements.end()) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800827 LogBufferElement* element = *it;
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800828
Mark Salyzyn58363792017-04-17 12:46:12 -0700829 if (oldest && (watermark <= element->getRealTime())) {
Mark Salyzyn0878a7c2017-05-11 13:28:33 -0700830 busy = isBusy(watermark);
831 // Do not let chatty eliding trigger any reader mitigation
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800832 break;
833 }
834
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700835 if (element->getLogId() != id) {
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800836 ++it;
837 continue;
838 }
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700839 // below this point element->getLogId() == id
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800840
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800841 if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) {
842 mLast[id] = it;
843 mLastSet[id] = true;
844 }
845
Chih-Hung Hsieh08d470b2018-08-13 14:22:56 -0700846 uint16_t dropped = element->getDropped();
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800847
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700848 // remove any leading drops
849 if (leading && dropped) {
850 it = erase(it);
851 continue;
852 }
853
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700854 if (dropped && last.coalesce(element, dropped)) {
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700855 it = erase(it, true);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700856 continue;
857 }
858
Mark Salyzyn501c3732017-03-10 14:31:54 -0800859 int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY))
860 ? element->getTag()
861 : element->getUid();
Mark Salyzyn6a066942016-07-14 15:34:30 -0700862
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700863 if (hasBlacklist && mPrune.naughty(element)) {
864 last.clear(element);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700865 it = erase(it);
866 if (dropped) {
867 continue;
868 }
869
870 pruneRows--;
871 if (pruneRows == 0) {
872 break;
873 }
874
Mark Salyzyn6a066942016-07-14 15:34:30 -0700875 if (key == worst) {
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700876 kick = true;
877 if (worst_sizes < second_worst_sizes) {
878 break;
879 }
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700880 worst_sizes -= element->getMsgLen();
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700881 }
882 continue;
883 }
884
Mark Salyzyn501c3732017-03-10 14:31:54 -0800885 if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old)) ||
886 (element->getRealTime() > (*lastt)->getRealTime())) {
Mark Salyzynccfe8442015-08-24 13:43:27 -0700887 break;
888 }
889
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700890 if (dropped) {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700891 last.add(element);
Mark Salyzyn501c3732017-03-10 14:31:54 -0800892 if (worstPid &&
893 ((!gc && (element->getPid() == worstPid)) ||
894 (mLastWorstPidOfSystem[id].find(element->getPid()) ==
895 mLastWorstPidOfSystem[id].end()))) {
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700896 // element->getUid() may not be AID_SYSTEM, next best
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700897 // watermark if current one empty. id is not LOG_ID_EVENTS
898 // or LOG_ID_SECURITY because of worstPid check.
Mark Salyzyn1eefca22016-09-01 07:28:44 -0700899 mLastWorstPidOfSystem[id][element->getPid()] = it;
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700900 }
Mark Salyzyn501c3732017-03-10 14:31:54 -0800901 if ((!gc && !worstPid && (key == worst)) ||
902 (mLastWorst[id].find(key) == mLastWorst[id].end())) {
Mark Salyzyn6a066942016-07-14 15:34:30 -0700903 mLastWorst[id][key] = it;
Mark Salyzyn49afe0d2015-08-24 13:43:27 -0700904 }
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800905 ++it;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700906 continue;
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800907 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700908
Mark Salyzyn501c3732017-03-10 14:31:54 -0800909 if ((key != worst) ||
910 (worstPid && (element->getPid() != worstPid))) {
Mark Salyzyn59212762015-06-01 09:41:19 -0700911 leading = false;
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700912 last.clear(element);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700913 ++it;
914 continue;
915 }
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700916 // key == worst below here
917 // If worstPid set, then element->getPid() == worstPid below here
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700918
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700919 pruneRows--;
920 if (pruneRows == 0) {
921 break;
922 }
923
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700924 kick = true;
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700925
Chih-Hung Hsieh08d470b2018-08-13 14:22:56 -0700926 uint16_t len = element->getMsgLen();
Mark Salyzyn5392aac2015-05-22 10:03:31 -0700927
928 // do not create any leading drops
929 if (leading) {
930 it = erase(it);
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700931 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700932 stats.drop(element);
933 element->setDropped(1);
934 if (last.coalesce(element, 1)) {
Mark Salyzynaaad42f2015-09-30 07:40:09 -0700935 it = erase(it, true);
Mark Salyzyn5392aac2015-05-22 10:03:31 -0700936 } else {
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700937 last.add(element);
Mark Salyzyn501c3732017-03-10 14:31:54 -0800938 if (worstPid &&
939 (!gc || (mLastWorstPidOfSystem[id].find(worstPid) ==
940 mLastWorstPidOfSystem[id].end()))) {
Mark Salyzynfa07f9d2016-10-21 09:46:42 -0700941 // element->getUid() may not be AID_SYSTEM, next best
Mark Salyzyn8fcfd852016-10-24 08:20:26 -0700942 // watermark if current one empty. id is not
943 // LOG_ID_EVENTS or LOG_ID_SECURITY because of worstPid.
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700944 mLastWorstPidOfSystem[id][worstPid] = it;
945 }
Mark Salyzyn6a066942016-07-14 15:34:30 -0700946 if ((!gc && !worstPid) ||
Mark Salyzyn501c3732017-03-10 14:31:54 -0800947 (mLastWorst[id].find(worst) == mLastWorst[id].end())) {
Mark Salyzyn6a066942016-07-14 15:34:30 -0700948 mLastWorst[id][worst] = it;
Mark Salyzyn5bb29722015-09-08 09:12:51 -0700949 }
Mark Salyzyn5392aac2015-05-22 10:03:31 -0700950 ++it;
951 }
Mark Salyzynab0dcf62015-03-16 12:04:09 -0700952 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700953 if (worst_sizes < second_worst_sizes) {
954 break;
955 }
956 worst_sizes -= len;
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800957 }
Mark Salyzyn2c9d9092015-04-17 15:38:04 -0700958 last.clear();
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800959
Mark Salyzyn1c950472014-04-01 17:19:47 -0700960 if (!kick || !mPrune.worstUidEnabled()) {
Mark Salyzyn501c3732017-03-10 14:31:54 -0800961 break; // the following loop will ask bad clients to skip/drop
Mark Salyzyn64d6fe92014-02-06 18:11:13 -0800962 }
963 }
964
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800965 bool whitelist = false;
Mark Salyzyn083b0372015-12-04 10:59:45 -0800966 bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll;
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800967 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -0800968 while ((pruneRows > 0) && (it != mLogElements.end())) {
969 LogBufferElement* element = *it;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700970
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700971 if (element->getLogId() != id) {
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700972 it++;
973 continue;
974 }
975
Mark Salyzyn507eb9f2016-01-11 10:58:09 -0800976 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
977 mLast[id] = it;
978 mLastSet[id] = true;
979 }
980
Mark Salyzyn58363792017-04-17 12:46:12 -0700981 if (oldest && (watermark <= element->getRealTime())) {
Mark Salyzyn0878a7c2017-05-11 13:28:33 -0700982 busy = isBusy(watermark);
983 if (!whitelist && busy) kickMe(oldest, id, pruneRows);
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700984 break;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800985 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700986
Mark Salyzynbec3c3d2015-08-28 08:02:59 -0700987 if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) {
988 // WhiteListed
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700989 whitelist = true;
990 it++;
991 continue;
992 }
993
994 it = erase(it);
995 pruneRows--;
Mark Salyzyn0175b072014-02-26 09:50:16 -0800996 }
997
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -0700998 // Do not save the whitelist if we are reader range limited
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800999 if (whitelist && (pruneRows > 0)) {
Mark Salyzyn507eb9f2016-01-11 10:58:09 -08001000 it = mLastSet[id] ? mLast[id] : mLogElements.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -08001001 while ((it != mLogElements.end()) && (pruneRows > 0)) {
1002 LogBufferElement* element = *it;
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -07001003
Mark Salyzynbec3c3d2015-08-28 08:02:59 -07001004 if (element->getLogId() != id) {
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -07001005 ++it;
1006 continue;
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001007 }
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -07001008
Mark Salyzyn507eb9f2016-01-11 10:58:09 -08001009 if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
1010 mLast[id] = it;
1011 mLastSet[id] = true;
1012 }
1013
Mark Salyzyn58363792017-04-17 12:46:12 -07001014 if (oldest && (watermark <= element->getRealTime())) {
Mark Salyzyn0878a7c2017-05-11 13:28:33 -07001015 busy = isBusy(watermark);
1016 if (busy) kickMe(oldest, id, pruneRows);
Mark Salyzyn97c1c2b2015-03-10 13:51:35 -07001017 break;
1018 }
1019
1020 it = erase(it);
1021 pruneRows--;
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001022 }
1023 }
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001024
Mark Salyzyn0175b072014-02-26 09:50:16 -08001025 LogTimeEntry::unlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001026
1027 return (pruneRows > 0) && busy;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001028}
1029
1030// clear all rows of type "id" from the buffer.
Mark Salyzync5dc9702015-09-16 15:34:00 -07001031bool LogBuffer::clear(log_id_t id, uid_t uid) {
1032 bool busy = true;
1033 // If it takes more than 4 tries (seconds) to clear, then kill reader(s)
1034 for (int retry = 4;;) {
Mark Salyzyn501c3732017-03-10 14:31:54 -08001035 if (retry == 1) { // last pass
Mark Salyzync5dc9702015-09-16 15:34:00 -07001036 // Check if it is still busy after the sleep, we say prune
1037 // one entry, not another clear run, so we are looking for
1038 // the quick side effect of the return value to tell us if
1039 // we have a _blocked_ reader.
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001040 wrlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001041 busy = prune(id, 1, uid);
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001042 unlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001043 // It is still busy, blocked reader(s), lets kill them all!
1044 // otherwise, lets be a good citizen and preserve the slow
1045 // readers and let the clear run (below) deal with determining
1046 // if we are still blocked and return an error code to caller.
1047 if (busy) {
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001048 LogTimeEntry::wrlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001049 LastLogTimes::iterator times = mTimes.begin();
1050 while (times != mTimes.end()) {
Tom Cherry4f227862018-10-08 17:33:50 -07001051 LogTimeEntry* entry = times->get();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001052 // Killer punch
Tom Cherry4f227862018-10-08 17:33:50 -07001053 if (entry->isWatching(id)) {
Mark Salyzync5dc9702015-09-16 15:34:00 -07001054 entry->release_Locked();
1055 }
1056 times++;
1057 }
1058 LogTimeEntry::unlock();
1059 }
1060 }
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001061 wrlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001062 busy = prune(id, ULONG_MAX, uid);
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001063 unlock();
Mark Salyzync5dc9702015-09-16 15:34:00 -07001064 if (!busy || !--retry) {
1065 break;
1066 }
Mark Salyzyn501c3732017-03-10 14:31:54 -08001067 sleep(1); // Let reader(s) catch up after notification
Mark Salyzync5dc9702015-09-16 15:34:00 -07001068 }
1069 return busy;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001070}
1071
1072// get the used space associated with "id".
1073unsigned long LogBuffer::getSizeUsed(log_id_t id) {
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001074 rdlock();
Mark Salyzyn34facab2014-02-06 14:48:50 -08001075 size_t retval = stats.sizes(id);
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001076 unlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -08001077 return retval;
1078}
1079
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001080// set the total space allocated to "id"
1081int LogBuffer::setSize(log_id_t id, unsigned long size) {
1082 // Reasonable limits ...
Mark Salyzynf10e2732016-09-27 13:08:23 -07001083 if (!__android_logger_valid_buffer_size(size)) {
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001084 return -1;
1085 }
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001086 wrlock();
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001087 log_buffer_size(id) = size;
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001088 unlock();
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001089 return 0;
1090}
1091
1092// get the total space allocated to "id"
1093unsigned long LogBuffer::getSize(log_id_t id) {
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001094 rdlock();
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001095 size_t retval = log_buffer_size(id);
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001096 unlock();
Mark Salyzyndfa7a072014-02-11 12:29:31 -08001097 return retval;
1098}
1099
Mark Salyzynae2abf12017-03-31 10:48:39 -07001100log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
1101 pid_t* lastTid, bool privileged, bool security,
1102 int (*filter)(const LogBufferElement* element,
1103 void* arg),
1104 void* arg) {
Mark Salyzyn0175b072014-02-26 09:50:16 -08001105 LogBufferElementCollection::iterator it;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001106 uid_t uid = reader->getUid();
1107
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001108 rdlock();
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001109
Mark Salyzyn5a34d6e2017-03-10 08:44:14 -08001110 if (start == log_time::EPOCH) {
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001111 // client wants to start from the beginning
1112 it = mLogElements.begin();
1113 } else {
Mark Salyzyn0f92fdc2017-04-04 10:57:41 -07001114 // Cap to 300 iterations we look back for out-of-order entries.
1115 size_t count = 300;
Mark Salyzyn58363792017-04-17 12:46:12 -07001116
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001117 // Client wants to start from some specified time. Chances are
1118 // we are better off starting from the end of the time sorted list.
Mark Salyzyn58363792017-04-17 12:46:12 -07001119 LogBufferElementCollection::iterator last;
Mark Salyzyn1f467162017-03-27 13:12:41 -07001120 for (last = it = mLogElements.end(); it != mLogElements.begin();
Mark Salyzyn501c3732017-03-10 14:31:54 -08001121 /* do nothing */) {
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001122 --it;
Mark Salyzyn501c3732017-03-10 14:31:54 -08001123 LogBufferElement* element = *it;
Mark Salyzyn3b941d42017-03-10 10:31:48 -08001124 if (element->getRealTime() > start) {
1125 last = it;
Mark Salyzyn206ed8e2017-05-18 10:06:00 -07001126 } else if (element->getRealTime() == start) {
1127 last = ++it;
1128 break;
Joe Onorato4bba6982018-04-04 14:35:34 -07001129 } else if (!--count) {
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001130 break;
1131 }
1132 }
Mark Salyzyn3b941d42017-03-10 10:31:48 -08001133 it = last;
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001134 }
1135
Mark Salyzyn206ed8e2017-05-18 10:06:00 -07001136 log_time curr = start;
Mark Salyzynb5b87962017-01-23 14:20:31 -08001137
Mark Salyzyn3614a0c2017-04-17 12:46:12 -07001138 LogBufferElement* lastElement = nullptr; // iterator corruption paranoia
1139 static const size_t maxSkip = 4194304; // maximum entries to skip
1140 size_t skip = maxSkip;
Dragoslav Mitrinovic8e8e8db2015-01-15 09:29:43 -06001141 for (; it != mLogElements.end(); ++it) {
Mark Salyzyn501c3732017-03-10 14:31:54 -08001142 LogBufferElement* element = *it;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001143
Mark Salyzyn3614a0c2017-04-17 12:46:12 -07001144 if (!--skip) {
1145 android::prdebug("reader.per: too many elements skipped");
1146 break;
1147 }
1148 if (element == lastElement) {
1149 android::prdebug("reader.per: identical elements");
1150 break;
1151 }
1152 lastElement = element;
1153
Mark Salyzyn0175b072014-02-26 09:50:16 -08001154 if (!privileged && (element->getUid() != uid)) {
1155 continue;
1156 }
1157
Mark Salyzyn8fa88962016-01-26 14:32:35 -08001158 if (!security && (element->getLogId() == LOG_ID_SECURITY)) {
1159 continue;
1160 }
1161
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001162 // NB: calling out to another object with wrlock() held (safe)
Mark Salyzynf7c0f752015-03-03 13:39:37 -08001163 if (filter) {
1164 int ret = (*filter)(element, arg);
1165 if (ret == false) {
1166 continue;
1167 }
1168 if (ret != true) {
1169 break;
1170 }
Mark Salyzyn0175b072014-02-26 09:50:16 -08001171 }
1172
Mark Salyzynae2abf12017-03-31 10:48:39 -07001173 bool sameTid = false;
1174 if (lastTid) {
1175 sameTid = lastTid[element->getLogId()] == element->getTid();
1176 // Dropped (chatty) immediately following a valid log from the
1177 // same source in the same log buffer indicates we have a
1178 // multiple identical squash. chatty that differs source
1179 // is due to spam filter. chatty to chatty of different
1180 // source is also due to spam filter.
1181 lastTid[element->getLogId()] =
1182 (element->getDropped() && !sameTid) ? 0 : element->getTid();
1183 }
Mark Salyzynb5b87962017-01-23 14:20:31 -08001184
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001185 unlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -08001186
1187 // range locking in LastLogTimes looks after us
Mark Salyzyn206ed8e2017-05-18 10:06:00 -07001188 curr = element->flushTo(reader, this, privileged, sameTid);
Mark Salyzyn0175b072014-02-26 09:50:16 -08001189
Mark Salyzyn206ed8e2017-05-18 10:06:00 -07001190 if (curr == element->FLUSH_ERROR) {
1191 return curr;
Mark Salyzyneb45db22017-05-17 19:55:12 +00001192 }
Mark Salyzyn0175b072014-02-26 09:50:16 -08001193
Mark Salyzyn3614a0c2017-04-17 12:46:12 -07001194 skip = maxSkip;
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001195 rdlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -08001196 }
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001197 unlock();
Mark Salyzyn0175b072014-02-26 09:50:16 -08001198
Mark Salyzyn206ed8e2017-05-18 10:06:00 -07001199 return curr;
Mark Salyzyn0175b072014-02-26 09:50:16 -08001200}
Mark Salyzyn34facab2014-02-06 14:48:50 -08001201
Mark Salyzynee3b8382015-12-17 09:58:43 -08001202std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid,
1203 unsigned int logMask) {
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001204 wrlock();
Mark Salyzyn34facab2014-02-06 14:48:50 -08001205
Mark Salyzynee3b8382015-12-17 09:58:43 -08001206 std::string ret = stats.format(uid, pid, logMask);
Mark Salyzyn34facab2014-02-06 14:48:50 -08001207
Mark Salyzyn3c501b52017-04-18 14:09:45 -07001208 unlock();
Mark Salyzyn73160ac2015-08-20 10:01:44 -07001209
1210 return ret;
Mark Salyzyn34facab2014-02-06 14:48:50 -08001211}