Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1 | /* |
| 2 | * Copyright (C) 2012-2014 The Android Open Source Project |
| 3 | * |
| 4 | * Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | * you may not use this file except in compliance with the License. |
| 6 | * You may obtain a copy of the License at |
| 7 | * |
| 8 | * http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | * |
| 10 | * Unless required by applicable law or agreed to in writing, software |
| 11 | * distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | * See the License for the specific language governing permissions and |
| 14 | * limitations under the License. |
| 15 | */ |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 16 | // for manual checking of stale entries during LogBuffer::erase() |
| 17 | //#define DEBUG_CHECK_FOR_STALE_ENTRIES |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 18 | |
Mark Salyzyn | 4e756fb | 2014-05-06 07:34:59 -0700 | [diff] [blame] | 19 | #include <ctype.h> |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 20 | #include <endian.h> |
Mark Salyzyn | 88fe7cc | 2015-02-09 08:21:05 -0800 | [diff] [blame] | 21 | #include <errno.h> |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 22 | #include <stdio.h> |
| 23 | #include <string.h> |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 24 | #include <sys/cdefs.h> |
Mark Salyzyn | 7b85c59 | 2014-05-09 17:44:18 -0700 | [diff] [blame] | 25 | #include <sys/user.h> |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 26 | #include <time.h> |
| 27 | #include <unistd.h> |
| 28 | |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 29 | #include <unordered_map> |
| 30 | |
Mark Salyzyn | 4e756fb | 2014-05-06 07:34:59 -0700 | [diff] [blame] | 31 | #include <cutils/properties.h> |
Mark Salyzyn | b004083 | 2016-09-27 13:08:23 -0700 | [diff] [blame] | 32 | #include <private/android_logger.h> |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 33 | |
| 34 | #include "LogBuffer.h" |
Mark Salyzyn | 0e2fe42 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 35 | #include "LogKlog.h" |
Mark Salyzyn | 4e756fb | 2014-05-06 07:34:59 -0700 | [diff] [blame] | 36 | #include "LogReader.h" |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 37 | #include "LogUtils.h" |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 38 | |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 39 | #ifndef __predict_false |
| 40 | #define __predict_false(exp) __builtin_expect((exp) != 0, 0) |
| 41 | #endif |
| 42 | |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 43 | // Default |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 44 | #define log_buffer_size(id) mMaxSize[id] |
Mark Salyzyn | 4e756fb | 2014-05-06 07:34:59 -0700 | [diff] [blame] | 45 | |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 46 | const log_time LogBuffer::pruneMargin(3, 0); |
| 47 | |
Mark Salyzyn | 3fe2593 | 2015-03-10 16:45:17 -0700 | [diff] [blame] | 48 | void LogBuffer::init() { |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 49 | log_id_for_each(i) { |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 50 | mLastSet[i] = false; |
| 51 | mLast[i] = mLogElements.begin(); |
| 52 | |
Mark Salyzyn | b004083 | 2016-09-27 13:08:23 -0700 | [diff] [blame] | 53 | if (setSize(i, __android_logger_get_buffer_size(i))) { |
Mark Salyzyn | 7b85c59 | 2014-05-09 17:44:18 -0700 | [diff] [blame] | 54 | setSize(i, LOG_BUFFER_MIN_SIZE); |
| 55 | } |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 56 | } |
Mark Salyzyn | 0e2fe42 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 57 | bool lastMonotonic = monotonic; |
Mark Salyzyn | 11a3e70 | 2015-12-01 15:57:25 -0800 | [diff] [blame] | 58 | monotonic = android_log_clockid() == CLOCK_MONOTONIC; |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 59 | 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 Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 75 | rdlock(); |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 76 | LogBufferElementCollection::iterator it = mLogElements.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 77 | while ((it != mLogElements.end())) { |
| 78 | LogBufferElement* e = *it; |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 79 | if (monotonic) { |
| 80 | if (!android::isMonotonic(e->mRealTime)) { |
| 81 | LogKlog::convertRealToMonotonic(e->mRealTime); |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 82 | if ((e->mRealTime.tv_nsec % 1000) == 0) { |
| 83 | e->mRealTime.tv_nsec++; |
| 84 | } |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 85 | } |
| 86 | } else { |
| 87 | if (android::isMonotonic(e->mRealTime)) { |
| 88 | LogKlog::convertMonotonicToReal(e->mRealTime); |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 89 | if ((e->mRealTime.tv_nsec % 1000) == 0) { |
| 90 | e->mRealTime.tv_nsec++; |
| 91 | } |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 92 | } |
| 93 | } |
| 94 | ++it; |
| 95 | } |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 96 | unlock(); |
Mark Salyzyn | 0e2fe42 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 97 | } |
| 98 | |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 99 | // We may have been triggered by a SIGHUP. Release any sleeping reader |
| 100 | // threads to dump their current content. |
Mark Salyzyn | 0e2fe42 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 101 | // |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 102 | // 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 Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 104 | LogTimeEntry::wrlock(); |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 105 | |
| 106 | LastLogTimes::iterator times = mTimes.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 107 | while (times != mTimes.end()) { |
| 108 | LogTimeEntry* entry = (*times); |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 109 | if (entry->owned_Locked()) { |
| 110 | entry->triggerReader_Locked(); |
Mark Salyzyn | 0e2fe42 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 111 | } |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 112 | times++; |
Mark Salyzyn | 0e2fe42 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 113 | } |
Mark Salyzyn | c959c64 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 114 | |
| 115 | LogTimeEntry::unlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 116 | } |
| 117 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 118 | LogBuffer::LogBuffer(LastLogTimes* times) |
| 119 | : monotonic(android_log_clockid() == CLOCK_MONOTONIC), mTimes(*times) { |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 120 | pthread_rwlock_init(&mLogElementsLock, nullptr); |
Mark Salyzyn | 3fe2593 | 2015-03-10 16:45:17 -0700 | [diff] [blame] | 121 | |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 122 | log_id_for_each(i) { |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 123 | lastLoggedElements[i] = nullptr; |
| 124 | droppedElements[i] = nullptr; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 125 | } |
| 126 | |
Mark Salyzyn | 3fe2593 | 2015-03-10 16:45:17 -0700 | [diff] [blame] | 127 | init(); |
| 128 | } |
| 129 | |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 130 | LogBuffer::~LogBuffer() { |
| 131 | log_id_for_each(i) { |
| 132 | delete lastLoggedElements[i]; |
| 133 | delete droppedElements[i]; |
| 134 | } |
| 135 | } |
| 136 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 137 | enum match_type { DIFFERENT, SAME, SAME_LIBLOG }; |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 138 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 139 | static enum match_type identical(LogBufferElement* elem, |
| 140 | LogBufferElement* last) { |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 141 | // is it mostly identical? |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 142 | // if (!elem) return DIFFERENT; |
Mark Salyzyn | 530bd6c | 2016-08-11 08:02:06 -0700 | [diff] [blame] | 143 | ssize_t lenl = elem->getMsgLen(); |
| 144 | if (lenl <= 0) return DIFFERENT; // value if this represents a chatty elem |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 145 | // if (!last) return DIFFERENT; |
Mark Salyzyn | 530bd6c | 2016-08-11 08:02:06 -0700 | [diff] [blame] | 146 | ssize_t lenr = last->getMsgLen(); |
| 147 | if (lenr <= 0) return DIFFERENT; // value if this represents a chatty elem |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 148 | // if (elem->getLogId() != last->getLogId()) return DIFFERENT; |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 149 | if (elem->getUid() != last->getUid()) return DIFFERENT; |
| 150 | if (elem->getPid() != last->getPid()) return DIFFERENT; |
| 151 | if (elem->getTid() != last->getTid()) return DIFFERENT; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 152 | |
| 153 | // last is more than a minute old, stop squashing identical messages |
| 154 | if (elem->getRealTime().nsec() > |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 155 | (last->getRealTime().nsec() + 60 * NS_PER_SEC)) |
| 156 | return DIFFERENT; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 157 | |
| 158 | // Identical message |
| 159 | const char* msgl = elem->getMsg(); |
| 160 | const char* msgr = last->getMsg(); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 161 | if (lenl == lenr) { |
| 162 | if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME; |
| 163 | // liblog tagged messages (content gets summed) |
| 164 | if ((elem->getLogId() == LOG_ID_EVENTS) && |
| 165 | (lenl == sizeof(android_log_event_int_t)) && |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 166 | !fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_int_t) - |
| 167 | sizeof(int32_t)) && |
| 168 | (elem->getTag() == LIBLOG_LOG_TAG)) |
| 169 | return SAME_LIBLOG; |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 170 | } |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 171 | |
| 172 | // audit message (except sequence number) identical? |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 173 | if (last->isBinary()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 174 | if (fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_string_t) - |
| 175 | sizeof(int32_t))) |
| 176 | return DIFFERENT; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 177 | msgl += sizeof(android_log_event_string_t); |
| 178 | lenl -= sizeof(android_log_event_string_t); |
| 179 | msgr += sizeof(android_log_event_string_t); |
| 180 | lenr -= sizeof(android_log_event_string_t); |
| 181 | } |
Mark Salyzyn | 530bd6c | 2016-08-11 08:02:06 -0700 | [diff] [blame] | 182 | static const char avc[] = "): avc: "; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 183 | const char* avcl = android::strnstr(msgl, lenl, avc); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 184 | if (!avcl) return DIFFERENT; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 185 | lenl -= avcl - msgl; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 186 | const char* avcr = android::strnstr(msgr, lenr, avc); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 187 | if (!avcr) return DIFFERENT; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 188 | lenr -= avcr - msgr; |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 189 | if (lenl != lenr) return DIFFERENT; |
Mark Salyzyn | 530bd6c | 2016-08-11 08:02:06 -0700 | [diff] [blame] | 190 | if (fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), |
Evgenii Stepanov | 2d67330 | 2017-03-14 14:47:25 -0700 | [diff] [blame] | 191 | lenl - strlen(avc))) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 192 | return DIFFERENT; |
Evgenii Stepanov | 2d67330 | 2017-03-14 14:47:25 -0700 | [diff] [blame] | 193 | } |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 194 | return SAME; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 195 | } |
| 196 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 197 | int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, |
| 198 | pid_t tid, const char* msg, unsigned short len) { |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 199 | if ((log_id >= LOG_ID_MAX) || (log_id < 0)) { |
Mark Salyzyn | 88fe7cc | 2015-02-09 08:21:05 -0800 | [diff] [blame] | 200 | return -EINVAL; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 201 | } |
Mark Salyzyn | 0dcfae6 | 2014-10-02 13:07:05 -0700 | [diff] [blame] | 202 | |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 203 | // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns. |
| 204 | // This prevents any chance that an outside source can request an |
| 205 | // exact entry with time specified in ms or us precision. |
| 206 | if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec; |
| 207 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 208 | LogBufferElement* elem = |
| 209 | new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len); |
Mark Salyzyn | c55cc11 | 2016-01-06 21:17:43 +0000 | [diff] [blame] | 210 | if (log_id != LOG_ID_SECURITY) { |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 211 | int prio = ANDROID_LOG_INFO; |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 212 | const char* tag = nullptr; |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 213 | if (log_id == LOG_ID_EVENTS) { |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 214 | tag = tagToName(elem->getTag()); |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 215 | } else { |
| 216 | prio = *msg; |
| 217 | tag = msg + 1; |
| 218 | } |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 219 | if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) { |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 220 | // Log traffic received to total |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 221 | wrlock(); |
Mark Salyzyn | fb0967b | 2017-04-14 09:46:57 -0700 | [diff] [blame] | 222 | stats.addTotal(elem); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 223 | unlock(); |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 224 | delete elem; |
| 225 | return -EACCES; |
| 226 | } |
Mark Salyzyn | 0dcfae6 | 2014-10-02 13:07:05 -0700 | [diff] [blame] | 227 | } |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 228 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 229 | wrlock(); |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 230 | LogBufferElement* currentLast = lastLoggedElements[log_id]; |
| 231 | if (currentLast) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 232 | LogBufferElement* dropped = droppedElements[log_id]; |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 233 | unsigned short count = dropped ? dropped->getDropped() : 0; |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 234 | // |
| 235 | // State Init |
| 236 | // incoming: |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 237 | // dropped = nullptr |
| 238 | // currentLast = nullptr; |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 239 | // elem = incoming message |
| 240 | // outgoing: |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 241 | // dropped = nullptr -> State 0 |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 242 | // currentLast = copy of elem |
| 243 | // log elem |
| 244 | // State 0 |
| 245 | // incoming: |
| 246 | // count = 0 |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 247 | // dropped = nullptr |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 248 | // currentLast = copy of last message |
| 249 | // elem = incoming message |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 250 | // outgoing: if match != DIFFERENT |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 251 | // dropped = copy of first identical message -> State 1 |
| 252 | // currentLast = reference to elem |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 253 | // break: if match == DIFFERENT |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 254 | // dropped = nullptr -> State 0 |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 255 | // delete copy of last message (incoming currentLast) |
| 256 | // currentLast = copy of elem |
| 257 | // log elem |
| 258 | // State 1 |
| 259 | // incoming: |
| 260 | // count = 0 |
| 261 | // dropped = copy of first identical message |
| 262 | // currentLast = reference to last held-back incoming |
| 263 | // message |
| 264 | // elem = incoming message |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 265 | // outgoing: if match == SAME |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 266 | // delete copy of first identical message (dropped) |
| 267 | // dropped = reference to last held-back incoming |
| 268 | // message set to chatty count of 1 -> State 2 |
| 269 | // currentLast = reference to elem |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 270 | // outgoing: if match == SAME_LIBLOG |
| 271 | // dropped = copy of first identical message -> State 1 |
| 272 | // take sum of currentLast and elem |
| 273 | // if sum overflows: |
| 274 | // log currentLast |
| 275 | // currentLast = reference to elem |
| 276 | // else |
| 277 | // delete currentLast |
| 278 | // currentLast = reference to elem, sum liblog. |
| 279 | // break: if match == DIFFERENT |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 280 | // delete dropped |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 281 | // dropped = nullptr -> State 0 |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 282 | // log reference to last held-back (currentLast) |
| 283 | // currentLast = copy of elem |
| 284 | // log elem |
| 285 | // State 2 |
| 286 | // incoming: |
| 287 | // count = chatty count |
| 288 | // dropped = chatty message holding count |
| 289 | // currentLast = reference to last held-back incoming |
| 290 | // message. |
| 291 | // dropped = chatty message holding count |
| 292 | // elem = incoming message |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 293 | // outgoing: if match != DIFFERENT |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 294 | // delete chatty message holding count |
| 295 | // dropped = reference to last held-back incoming |
| 296 | // message, set to chatty count + 1 |
| 297 | // currentLast = reference to elem |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 298 | // break: if match == DIFFERENT |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 299 | // log dropped (chatty message) |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 300 | // dropped = nullptr -> State 0 |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 301 | // log reference to last held-back (currentLast) |
| 302 | // currentLast = copy of elem |
| 303 | // log elem |
| 304 | // |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 305 | enum match_type match = identical(elem, currentLast); |
| 306 | if (match != DIFFERENT) { |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 307 | if (dropped) { |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 308 | // Sum up liblog tag messages? |
| 309 | if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) { |
| 310 | android_log_event_int_t* event = |
| 311 | reinterpret_cast<android_log_event_int_t*>( |
| 312 | const_cast<char*>(currentLast->getMsg())); |
| 313 | // |
| 314 | // To unit test, differentiate with something like: |
| 315 | // event->header.tag = htole32(CHATTY_LOG_TAG); |
| 316 | // here, then instead of delete currentLast below, |
| 317 | // log(currentLast) to see the incremental sums form. |
| 318 | // |
| 319 | uint32_t swab = event->payload.data; |
| 320 | unsigned long long total = htole32(swab); |
| 321 | event = reinterpret_cast<android_log_event_int_t*>( |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 322 | const_cast<char*>(elem->getMsg())); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 323 | swab = event->payload.data; |
| 324 | |
| 325 | lastLoggedElements[LOG_ID_EVENTS] = elem; |
| 326 | total += htole32(swab); |
| 327 | // check for overflow |
| 328 | if (total >= UINT32_MAX) { |
| 329 | log(currentLast); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 330 | unlock(); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 331 | return len; |
| 332 | } |
Mark Salyzyn | fb0967b | 2017-04-14 09:46:57 -0700 | [diff] [blame] | 333 | stats.addTotal(currentLast); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 334 | delete currentLast; |
| 335 | swab = total; |
| 336 | event->payload.data = htole32(swab); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 337 | unlock(); |
Mark Salyzyn | 60b9992 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 338 | return len; |
| 339 | } |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 340 | if (count == USHRT_MAX) { |
| 341 | log(dropped); |
| 342 | count = 1; |
| 343 | } else { |
| 344 | delete dropped; |
| 345 | ++count; |
| 346 | } |
| 347 | } |
| 348 | if (count) { |
Mark Salyzyn | fb0967b | 2017-04-14 09:46:57 -0700 | [diff] [blame] | 349 | stats.addTotal(currentLast); |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 350 | currentLast->setDropped(count); |
| 351 | } |
| 352 | droppedElements[log_id] = currentLast; |
| 353 | lastLoggedElements[log_id] = elem; |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 354 | unlock(); |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 355 | return len; |
| 356 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 357 | if (dropped) { // State 1 or 2 |
| 358 | if (count) { // State 2 |
| 359 | log(dropped); // report chatty |
| 360 | } else { // State 1 |
| 361 | delete dropped; |
Mark Salyzyn | 52ee5f5 | 2016-12-16 16:09:15 -0800 | [diff] [blame] | 362 | } |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 363 | droppedElements[log_id] = nullptr; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 364 | log(currentLast); // report last message in the series |
| 365 | } else { // State 0 |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 366 | delete currentLast; |
| 367 | } |
| 368 | } |
| 369 | lastLoggedElements[log_id] = new LogBufferElement(*elem); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 370 | |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 371 | log(elem); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 372 | unlock(); |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 373 | |
| 374 | return len; |
| 375 | } |
| 376 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 377 | // assumes LogBuffer::wrlock() held, owns elem, look after garbage collection |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 378 | void LogBuffer::log(LogBufferElement* elem) { |
Mark Salyzyn | 55b8a4e | 2017-03-14 13:11:12 -0700 | [diff] [blame] | 379 | // cap on how far back we will sort in-place, otherwise append |
| 380 | static uint32_t too_far_back = 5; // five seconds |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 381 | // Insert elements in time sorted order if possible |
| 382 | // NB: if end is region locked, place element at end of list |
| 383 | LogBufferElementCollection::iterator it = mLogElements.end(); |
| 384 | LogBufferElementCollection::iterator last = it; |
Mark Salyzyn | 5119249 | 2017-03-03 10:21:23 -0800 | [diff] [blame] | 385 | if (__predict_true(it != mLogElements.begin())) --it; |
| 386 | if (__predict_false(it == mLogElements.begin()) || |
Mark Salyzyn | 55b8a4e | 2017-03-14 13:11:12 -0700 | [diff] [blame] | 387 | __predict_true((*it)->getRealTime() <= elem->getRealTime()) || |
| 388 | __predict_false((((*it)->getRealTime().tv_sec - too_far_back) > |
| 389 | elem->getRealTime().tv_sec) && |
| 390 | (elem->getLogId() != LOG_ID_KERNEL) && |
| 391 | ((*it)->getLogId() != LOG_ID_KERNEL))) { |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 392 | mLogElements.push_back(elem); |
| 393 | } else { |
Mark Salyzyn | d18255f | 2017-03-10 08:44:14 -0800 | [diff] [blame] | 394 | log_time end = log_time::EPOCH; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 395 | bool end_set = false; |
| 396 | bool end_always = false; |
| 397 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 398 | LogTimeEntry::rdlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 399 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 400 | LastLogTimes::iterator times = mTimes.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 401 | while (times != mTimes.end()) { |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 402 | LogTimeEntry* entry = (*times); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 403 | if (entry->owned_Locked()) { |
| 404 | if (!entry->mNonBlock) { |
| 405 | end_always = true; |
| 406 | break; |
| 407 | } |
Mark Salyzyn | 5119249 | 2017-03-03 10:21:23 -0800 | [diff] [blame] | 408 | // it passing mEnd is blocked by the following checks. |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 409 | if (!end_set || (end <= entry->mEnd)) { |
| 410 | end = entry->mEnd; |
| 411 | end_set = true; |
| 412 | } |
| 413 | } |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 414 | times++; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 415 | } |
| 416 | |
Mark Salyzyn | d18255f | 2017-03-10 08:44:14 -0800 | [diff] [blame] | 417 | if (end_always || (end_set && (end > (*it)->getRealTime()))) { |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 418 | mLogElements.push_back(elem); |
| 419 | } else { |
Mark Salyzyn | 5119249 | 2017-03-03 10:21:23 -0800 | [diff] [blame] | 420 | // should be short as timestamps are localized near end() |
| 421 | do { |
| 422 | last = it; |
| 423 | if (__predict_false(it == mLogElements.begin())) { |
| 424 | break; |
| 425 | } |
Mark Salyzyn | 5119249 | 2017-03-03 10:21:23 -0800 | [diff] [blame] | 426 | --it; |
| 427 | } while (((*it)->getRealTime() > elem->getRealTime()) && |
Mark Salyzyn | d18255f | 2017-03-10 08:44:14 -0800 | [diff] [blame] | 428 | (!end_set || (end <= (*it)->getRealTime()))); |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 429 | mLogElements.insert(last, elem); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 430 | } |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 431 | LogTimeEntry::unlock(); |
| 432 | } |
| 433 | |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 434 | stats.add(elem); |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 435 | maybePrune(elem->getLogId()); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 436 | } |
| 437 | |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 438 | // Prune at most 10% of the log entries or maxPrune, whichever is less. |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 439 | // |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 440 | // LogBuffer::wrlock() must be held when this function is called. |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 441 | void LogBuffer::maybePrune(log_id_t id) { |
Mark Salyzyn | d774bce | 2014-02-06 14:48:50 -0800 | [diff] [blame] | 442 | size_t sizes = stats.sizes(id); |
Mark Salyzyn | 5f19031 | 2015-08-10 10:23:56 -0700 | [diff] [blame] | 443 | unsigned long maxSize = log_buffer_size(id); |
| 444 | if (sizes > maxSize) { |
Mark Salyzyn | 185d8da | 2015-08-19 12:20:36 -0700 | [diff] [blame] | 445 | size_t sizeOver = sizes - ((maxSize * 9) / 10); |
Mark Salyzyn | 49858cc | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 446 | size_t elements = stats.realElements(id); |
| 447 | size_t minElements = elements / 100; |
| 448 | if (minElements < minPrune) { |
| 449 | minElements = minPrune; |
| 450 | } |
Mark Salyzyn | 5f19031 | 2015-08-10 10:23:56 -0700 | [diff] [blame] | 451 | unsigned long pruneRows = elements * sizeOver / sizes; |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 452 | if (pruneRows < minElements) { |
Mark Salyzyn | 5f19031 | 2015-08-10 10:23:56 -0700 | [diff] [blame] | 453 | pruneRows = minElements; |
Mark Salyzyn | 9d4e34e | 2014-01-13 16:37:51 -0800 | [diff] [blame] | 454 | } |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 455 | if (pruneRows > maxPrune) { |
| 456 | pruneRows = maxPrune; |
Mark Salyzyn | 185d8da | 2015-08-19 12:20:36 -0700 | [diff] [blame] | 457 | } |
Mark Salyzyn | 9d4e34e | 2014-01-13 16:37:51 -0800 | [diff] [blame] | 458 | prune(id, pruneRows); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 459 | } |
| 460 | } |
| 461 | |
Mark Salyzyn | 1fdf71f | 2015-09-03 16:08:50 -0700 | [diff] [blame] | 462 | LogBufferElementCollection::iterator LogBuffer::erase( |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 463 | LogBufferElementCollection::iterator it, bool coalesce) { |
| 464 | LogBufferElement* element = *it; |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 465 | log_id_t id = element->getLogId(); |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 466 | |
Mark Salyzyn | 1117818 | 2016-10-21 09:46:42 -0700 | [diff] [blame] | 467 | // Remove iterator references in the various lists that will become stale |
| 468 | // after the element is erased from the main logging list. |
| 469 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 470 | { // start of scope for found iterator |
| 471 | int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) |
| 472 | ? element->getTag() |
| 473 | : element->getUid(); |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 474 | LogBufferIteratorMap::iterator found = mLastWorst[id].find(key); |
| 475 | if ((found != mLastWorst[id].end()) && (it == found->second)) { |
| 476 | mLastWorst[id].erase(found); |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 477 | } |
Mark Salyzyn | 5af07be | 2015-08-19 17:06:11 -0700 | [diff] [blame] | 478 | } |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 479 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 480 | { // start of scope for pid found iterator |
Mark Salyzyn | 1117818 | 2016-10-21 09:46:42 -0700 | [diff] [blame] | 481 | // element->getUid() may not be AID_SYSTEM for next-best-watermark. |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 482 | // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and |
| 483 | // long term code stability, find() check should be fast for those ids. |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 484 | LogBufferPidIteratorMap::iterator found = |
| 485 | mLastWorstPidOfSystem[id].find(element->getPid()); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 486 | if ((found != mLastWorstPidOfSystem[id].end()) && |
| 487 | (it == found->second)) { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 488 | mLastWorstPidOfSystem[id].erase(found); |
| 489 | } |
| 490 | } |
| 491 | |
Mark Salyzyn | 75d5cf0 | 2016-01-19 16:04:41 -0800 | [diff] [blame] | 492 | bool setLast[LOG_ID_MAX]; |
| 493 | bool doSetLast = false; |
| 494 | log_id_for_each(i) { |
| 495 | doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]); |
| 496 | } |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 497 | #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES |
| 498 | LogBufferElementCollection::iterator bad = it; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 499 | int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) |
| 500 | ? element->getTag() |
| 501 | : element->getUid(); |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 502 | #endif |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 503 | it = mLogElements.erase(it); |
Mark Salyzyn | 75d5cf0 | 2016-01-19 16:04:41 -0800 | [diff] [blame] | 504 | if (doSetLast) { |
| 505 | log_id_for_each(i) { |
| 506 | if (setLast[i]) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 507 | if (__predict_false(it == mLogElements.end())) { // impossible |
Mark Salyzyn | 75d5cf0 | 2016-01-19 16:04:41 -0800 | [diff] [blame] | 508 | mLastSet[i] = false; |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 509 | mLast[i] = mLogElements.begin(); |
Mark Salyzyn | 75d5cf0 | 2016-01-19 16:04:41 -0800 | [diff] [blame] | 510 | } else { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 511 | mLast[i] = it; // push down the road as next-best-watermark |
Mark Salyzyn | 75d5cf0 | 2016-01-19 16:04:41 -0800 | [diff] [blame] | 512 | } |
| 513 | } |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 514 | } |
| 515 | } |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 516 | #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES |
| 517 | log_id_for_each(i) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 518 | for (auto b : mLastWorst[i]) { |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 519 | if (bad == b.second) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 520 | android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i, |
| 521 | b.first, key); |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 522 | } |
| 523 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 524 | for (auto b : mLastWorstPidOfSystem[i]) { |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 525 | if (bad == b.second) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 526 | android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i, |
| 527 | b.first); |
Mark Salyzyn | b338b95 | 2016-10-24 16:22:17 -0700 | [diff] [blame] | 528 | } |
| 529 | } |
| 530 | if (mLastSet[i] && (bad == mLast[i])) { |
| 531 | android::prdebug("stale mLast[%d]\n", i); |
| 532 | mLastSet[i] = false; |
| 533 | mLast[i] = mLogElements.begin(); |
| 534 | } |
| 535 | } |
| 536 | #endif |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 537 | if (coalesce) { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 538 | stats.erase(element); |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 539 | } else { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 540 | stats.subtract(element); |
Mark Salyzyn | 1fdf71f | 2015-09-03 16:08:50 -0700 | [diff] [blame] | 541 | } |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 542 | delete element; |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 543 | |
| 544 | return it; |
| 545 | } |
| 546 | |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 547 | // Define a temporary mechanism to report the last LogBufferElement pointer |
| 548 | // for the specified uid, pid and tid. Used below to help merge-sort when |
| 549 | // pruning for worst UID. |
| 550 | class LogBufferElementKey { |
| 551 | const union { |
| 552 | struct { |
Mark Salyzyn | 16aacd3 | 2016-12-13 12:44:20 -0800 | [diff] [blame] | 553 | uint32_t uid; |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 554 | uint16_t pid; |
| 555 | uint16_t tid; |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 556 | } __packed; |
| 557 | uint64_t value; |
| 558 | } __packed; |
| 559 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 560 | public: |
| 561 | LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) |
| 562 | : uid(uid), pid(pid), tid(tid) { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 563 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 564 | explicit LogBufferElementKey(uint64_t key) : value(key) { |
| 565 | } |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 566 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 567 | uint64_t getKey() { |
| 568 | return value; |
| 569 | } |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 570 | }; |
| 571 | |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 572 | class LogBufferElementLast { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 573 | typedef std::unordered_map<uint64_t, LogBufferElement*> LogBufferElementMap; |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 574 | LogBufferElementMap map; |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 575 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 576 | public: |
| 577 | bool coalesce(LogBufferElement* element, unsigned short dropped) { |
| 578 | LogBufferElementKey key(element->getUid(), element->getPid(), |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 579 | element->getTid()); |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 580 | LogBufferElementMap::iterator it = map.find(key.getKey()); |
| 581 | if (it != map.end()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 582 | LogBufferElement* found = it->second; |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 583 | unsigned short moreDropped = found->getDropped(); |
| 584 | if ((dropped + moreDropped) > USHRT_MAX) { |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 585 | map.erase(it); |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 586 | } else { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 587 | found->setDropped(dropped + moreDropped); |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 588 | return true; |
| 589 | } |
| 590 | } |
| 591 | return false; |
| 592 | } |
| 593 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 594 | void add(LogBufferElement* element) { |
| 595 | LogBufferElementKey key(element->getUid(), element->getPid(), |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 596 | element->getTid()); |
| 597 | map[key.getKey()] = element; |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 598 | } |
| 599 | |
Mark Salyzyn | be1a30c | 2015-04-20 14:08:56 -0700 | [diff] [blame] | 600 | inline void clear() { |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 601 | map.clear(); |
Mark Salyzyn | be1a30c | 2015-04-20 14:08:56 -0700 | [diff] [blame] | 602 | } |
| 603 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 604 | void clear(LogBufferElement* element) { |
Mark Salyzyn | d18255f | 2017-03-10 08:44:14 -0800 | [diff] [blame] | 605 | log_time current = |
| 606 | element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 607 | for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) { |
| 608 | LogBufferElement* mapElement = it->second; |
| 609 | if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) && |
Mark Salyzyn | d18255f | 2017-03-10 08:44:14 -0800 | [diff] [blame] | 610 | (current > mapElement->getRealTime())) { |
Mark Salyzyn | 6a40419 | 2015-05-19 09:12:30 -0700 | [diff] [blame] | 611 | it = map.erase(it); |
| 612 | } else { |
| 613 | ++it; |
Mark Salyzyn | be1a30c | 2015-04-20 14:08:56 -0700 | [diff] [blame] | 614 | } |
| 615 | } |
| 616 | } |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 617 | }; |
| 618 | |
Mark Salyzyn | 434f374 | 2017-05-11 13:28:33 -0700 | [diff] [blame] | 619 | // Determine if watermark is within pruneMargin + 1s from the end of the list, |
| 620 | // the caller will use this result to set an internal busy flag indicating |
| 621 | // the prune operation could not be completed because a reader is blocking |
| 622 | // the request. |
| 623 | bool LogBuffer::isBusy(log_time watermark) { |
| 624 | LogBufferElementCollection::iterator ei = mLogElements.end(); |
| 625 | --ei; |
| 626 | return watermark < ((*ei)->getRealTime() - pruneMargin - log_time(1, 0)); |
| 627 | } |
| 628 | |
| 629 | // If the selected reader is blocking our pruning progress, decide on |
| 630 | // what kind of mitigation is necessary to unblock the situation. |
| 631 | void LogBuffer::kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows) { |
| 632 | if (stats.sizes(id) > (2 * log_buffer_size(id))) { // +100% |
| 633 | // A misbehaving or slow reader has its connection |
| 634 | // dropped if we hit too much memory pressure. |
| 635 | me->release_Locked(); |
| 636 | } else if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) { |
| 637 | // Allow a blocked WRAP timeout reader to |
| 638 | // trigger and start reporting the log data. |
| 639 | me->triggerReader_Locked(); |
| 640 | } else { |
| 641 | // tell slow reader to skip entries to catch up |
| 642 | me->triggerSkip_Locked(id, pruneRows); |
| 643 | } |
| 644 | } |
| 645 | |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 646 | // prune "pruneRows" of type "id" from the buffer. |
| 647 | // |
Mark Salyzyn | e2827d5 | 2015-09-08 09:12:51 -0700 | [diff] [blame] | 648 | // This garbage collection task is used to expire log entries. It is called to |
| 649 | // remove all logs (clear), all UID logs (unprivileged clear), or every |
| 650 | // 256 or 10% of the total logs (whichever is less) to prune the logs. |
| 651 | // |
| 652 | // First there is a prep phase where we discover the reader region lock that |
| 653 | // acts as a backstop to any pruning activity to stop there and go no further. |
| 654 | // |
| 655 | // There are three major pruning loops that follow. All expire from the oldest |
| 656 | // entries. Since there are multiple log buffers, the Android logging facility |
| 657 | // will appear to drop entries 'in the middle' when looking at multiple log |
| 658 | // sources and buffers. This effect is slightly more prominent when we prune |
| 659 | // the worst offender by logging source. Thus the logs slowly loose content |
| 660 | // and value as you move back in time. This is preferred since chatty sources |
| 661 | // invariably move the logs value down faster as less chatty sources would be |
| 662 | // expired in the noise. |
| 663 | // |
| 664 | // The first loop performs blacklisting and worst offender pruning. Falling |
| 665 | // through when there are no notable worst offenders and have not hit the |
| 666 | // region lock preventing further worst offender pruning. This loop also looks |
| 667 | // after managing the chatty log entries and merging to help provide |
| 668 | // statistical basis for blame. The chatty entries are not a notification of |
| 669 | // how much logs you may have, but instead represent how much logs you would |
| 670 | // have had in a virtual log buffer that is extended to cover all the in-memory |
| 671 | // logs without loss. They last much longer than the represented pruned logs |
| 672 | // since they get multiplied by the gains in the non-chatty log sources. |
| 673 | // |
| 674 | // The second loop get complicated because an algorithm of watermarks and |
| 675 | // history is maintained to reduce the order and keep processing time |
| 676 | // down to a minimum at scale. These algorithms can be costly in the face |
| 677 | // of larger log buffers, or severly limited processing time granted to a |
| 678 | // background task at lowest priority. |
| 679 | // |
| 680 | // This second loop does straight-up expiration from the end of the logs |
| 681 | // (again, remember for the specified log buffer id) but does some whitelist |
| 682 | // preservation. Thus whitelist is a Hail Mary low priority, blacklists and |
| 683 | // spam filtration all take priority. This second loop also checks if a region |
| 684 | // lock is causing us to buffer too much in the logs to help the reader(s), |
| 685 | // and will tell the slowest reader thread to skip log entries, and if |
| 686 | // persistent and hits a further threshold, kill the reader thread. |
| 687 | // |
| 688 | // The third thread is optional, and only gets hit if there was a whitelist |
| 689 | // and more needs to be pruned against the backstop of the region lock. |
| 690 | // |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 691 | // LogBuffer::wrlock() must be held when this function is called. |
Mark Salyzyn | e2827d5 | 2015-09-08 09:12:51 -0700 | [diff] [blame] | 692 | // |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 693 | bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 694 | LogTimeEntry* oldest = nullptr; |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 695 | bool busy = false; |
Mark Salyzyn | 71541f3 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 696 | bool clearAll = pruneRows == ULONG_MAX; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 697 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 698 | LogTimeEntry::rdlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 699 | |
| 700 | // Region locked? |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 701 | LastLogTimes::iterator times = mTimes.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 702 | while (times != mTimes.end()) { |
| 703 | LogTimeEntry* entry = (*times); |
| 704 | if (entry->owned_Locked() && entry->isWatching(id) && |
| 705 | (!oldest || (oldest->mStart > entry->mStart) || |
| 706 | ((oldest->mStart == entry->mStart) && |
| 707 | (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) { |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 708 | oldest = entry; |
| 709 | } |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 710 | times++; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 711 | } |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 712 | log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max); |
| 713 | if (oldest) watermark = oldest->mStart - pruneMargin; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 714 | |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 715 | LogBufferElementCollection::iterator it; |
| 716 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 717 | if (__predict_false(caller_uid != AID_ROOT)) { // unlikely |
Mark Salyzyn | 9e0c78e | 2016-09-01 15:48:36 -0700 | [diff] [blame] | 718 | // Only here if clear all request from non system source, so chatty |
| 719 | // filter logistics is not required. |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 720 | it = mLastSet[id] ? mLast[id] : mLogElements.begin(); |
| 721 | while (it != mLogElements.end()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 722 | LogBufferElement* element = *it; |
Mark Salyzyn | 276d535 | 2014-06-12 11:16:16 -0700 | [diff] [blame] | 723 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 724 | if ((element->getLogId() != id) || |
| 725 | (element->getUid() != caller_uid)) { |
Mark Salyzyn | 71541f3 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 726 | ++it; |
| 727 | continue; |
| 728 | } |
| 729 | |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 730 | if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { |
| 731 | mLast[id] = it; |
| 732 | mLastSet[id] = true; |
| 733 | } |
| 734 | |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 735 | if (oldest && (watermark <= element->getRealTime())) { |
Mark Salyzyn | 434f374 | 2017-05-11 13:28:33 -0700 | [diff] [blame] | 736 | busy = isBusy(watermark); |
| 737 | if (busy) kickMe(oldest, id, pruneRows); |
Mark Salyzyn | 276d535 | 2014-06-12 11:16:16 -0700 | [diff] [blame] | 738 | break; |
| 739 | } |
| 740 | |
Mark Salyzyn | 71541f3 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 741 | it = erase(it); |
Mark Salyzyn | 9e0c78e | 2016-09-01 15:48:36 -0700 | [diff] [blame] | 742 | if (--pruneRows == 0) { |
| 743 | break; |
| 744 | } |
Mark Salyzyn | 276d535 | 2014-06-12 11:16:16 -0700 | [diff] [blame] | 745 | } |
| 746 | LogTimeEntry::unlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 747 | return busy; |
Mark Salyzyn | 276d535 | 2014-06-12 11:16:16 -0700 | [diff] [blame] | 748 | } |
| 749 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 750 | // prune by worst offenders; by blacklist, UID, and by PID of system UID |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 751 | bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty(); |
Mark Salyzyn | 71541f3 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 752 | while (!clearAll && (pruneRows > 0)) { |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 753 | // recalculate the worst offender on every batched pass |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 754 | int worst = -1; // not valid for getUid() or getKey() |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 755 | size_t worst_sizes = 0; |
| 756 | size_t second_worst_sizes = 0; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 757 | pid_t worstPid = 0; // POSIX guarantees PID != 0 |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 758 | |
Mark Salyzyn | 0e765c6 | 2015-03-17 17:17:25 -0700 | [diff] [blame] | 759 | if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) { |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 760 | // Calculate threshold as 12.5% of available storage |
| 761 | size_t threshold = log_buffer_size(id) / 8; |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 762 | |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 763 | if ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 764 | stats.sortTags(AID_ROOT, (pid_t)0, 2, id) |
| 765 | .findWorst(worst, worst_sizes, second_worst_sizes, |
| 766 | threshold); |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 767 | // per-pid filter for AID_SYSTEM sources is too complex |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 768 | } else { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 769 | stats.sort(AID_ROOT, (pid_t)0, 2, id) |
| 770 | .findWorst(worst, worst_sizes, second_worst_sizes, |
| 771 | threshold); |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 772 | |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 773 | if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 774 | stats.sortPids(worst, (pid_t)0, 2, id) |
| 775 | .findWorst(worstPid, worst_sizes, second_worst_sizes); |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 776 | } |
| 777 | } |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 778 | } |
| 779 | |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 780 | // skip if we have neither worst nor naughty filters |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 781 | if ((worst == -1) && !hasBlacklist) { |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 782 | break; |
| 783 | } |
| 784 | |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 785 | bool kick = false; |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 786 | bool leading = true; |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 787 | it = mLastSet[id] ? mLast[id] : mLogElements.begin(); |
Mark Salyzyn | e2827d5 | 2015-09-08 09:12:51 -0700 | [diff] [blame] | 788 | // Perform at least one mandatory garbage collection cycle in following |
| 789 | // - clear leading chatty tags |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 790 | // - coalesce chatty tags |
Mark Salyzyn | e2827d5 | 2015-09-08 09:12:51 -0700 | [diff] [blame] | 791 | // - check age-out of preserved logs |
| 792 | bool gc = pruneRows <= 1; |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 793 | if (!gc && (worst != -1)) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 794 | { // begin scope for worst found iterator |
| 795 | LogBufferIteratorMap::iterator found = |
| 796 | mLastWorst[id].find(worst); |
| 797 | if ((found != mLastWorst[id].end()) && |
| 798 | (found->second != mLogElements.end())) { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 799 | leading = false; |
| 800 | it = found->second; |
| 801 | } |
| 802 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 803 | if (worstPid) { // begin scope for pid worst found iterator |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 804 | // FYI: worstPid only set if !LOG_ID_EVENTS and |
| 805 | // !LOG_ID_SECURITY, not going to make that assumption ... |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 806 | LogBufferPidIteratorMap::iterator found = |
| 807 | mLastWorstPidOfSystem[id].find(worstPid); |
| 808 | if ((found != mLastWorstPidOfSystem[id].end()) && |
| 809 | (found->second != mLogElements.end())) { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 810 | leading = false; |
| 811 | it = found->second; |
| 812 | } |
Mark Salyzyn | 5af07be | 2015-08-19 17:06:11 -0700 | [diff] [blame] | 813 | } |
| 814 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 815 | static const timespec too_old = { EXPIRE_HOUR_THRESHOLD * 60 * 60, 0 }; |
Mark Salyzyn | 7f62d6b | 2015-08-24 13:43:27 -0700 | [diff] [blame] | 816 | LogBufferElementCollection::iterator lastt; |
| 817 | lastt = mLogElements.end(); |
| 818 | --lastt; |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 819 | LogBufferElementLast last; |
Mark Salyzyn | 5af07be | 2015-08-19 17:06:11 -0700 | [diff] [blame] | 820 | while (it != mLogElements.end()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 821 | LogBufferElement* element = *it; |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 822 | |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 823 | if (oldest && (watermark <= element->getRealTime())) { |
Mark Salyzyn | 434f374 | 2017-05-11 13:28:33 -0700 | [diff] [blame] | 824 | busy = isBusy(watermark); |
| 825 | // Do not let chatty eliding trigger any reader mitigation |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 826 | break; |
| 827 | } |
| 828 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 829 | if (element->getLogId() != id) { |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 830 | ++it; |
| 831 | continue; |
| 832 | } |
Mark Salyzyn | 1117818 | 2016-10-21 09:46:42 -0700 | [diff] [blame] | 833 | // below this point element->getLogId() == id |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 834 | |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 835 | if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) { |
| 836 | mLast[id] = it; |
| 837 | mLastSet[id] = true; |
| 838 | } |
| 839 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 840 | unsigned short dropped = element->getDropped(); |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 841 | |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 842 | // remove any leading drops |
| 843 | if (leading && dropped) { |
| 844 | it = erase(it); |
| 845 | continue; |
| 846 | } |
| 847 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 848 | if (dropped && last.coalesce(element, dropped)) { |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 849 | it = erase(it, true); |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 850 | continue; |
| 851 | } |
| 852 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 853 | int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) |
| 854 | ? element->getTag() |
| 855 | : element->getUid(); |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 856 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 857 | if (hasBlacklist && mPrune.naughty(element)) { |
| 858 | last.clear(element); |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 859 | it = erase(it); |
| 860 | if (dropped) { |
| 861 | continue; |
| 862 | } |
| 863 | |
| 864 | pruneRows--; |
| 865 | if (pruneRows == 0) { |
| 866 | break; |
| 867 | } |
| 868 | |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 869 | if (key == worst) { |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 870 | kick = true; |
| 871 | if (worst_sizes < second_worst_sizes) { |
| 872 | break; |
| 873 | } |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 874 | worst_sizes -= element->getMsgLen(); |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 875 | } |
| 876 | continue; |
| 877 | } |
| 878 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 879 | if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old)) || |
| 880 | (element->getRealTime() > (*lastt)->getRealTime())) { |
Mark Salyzyn | 7f62d6b | 2015-08-24 13:43:27 -0700 | [diff] [blame] | 881 | break; |
| 882 | } |
| 883 | |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 884 | if (dropped) { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 885 | last.add(element); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 886 | if (worstPid && |
| 887 | ((!gc && (element->getPid() == worstPid)) || |
| 888 | (mLastWorstPidOfSystem[id].find(element->getPid()) == |
| 889 | mLastWorstPidOfSystem[id].end()))) { |
Mark Salyzyn | 1117818 | 2016-10-21 09:46:42 -0700 | [diff] [blame] | 890 | // element->getUid() may not be AID_SYSTEM, next best |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 891 | // watermark if current one empty. id is not LOG_ID_EVENTS |
| 892 | // or LOG_ID_SECURITY because of worstPid check. |
Mark Salyzyn | ce50dec | 2016-09-01 07:28:44 -0700 | [diff] [blame] | 893 | mLastWorstPidOfSystem[id][element->getPid()] = it; |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 894 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 895 | if ((!gc && !worstPid && (key == worst)) || |
| 896 | (mLastWorst[id].find(key) == mLastWorst[id].end())) { |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 897 | mLastWorst[id][key] = it; |
Mark Salyzyn | 76aab49 | 2015-08-24 13:43:27 -0700 | [diff] [blame] | 898 | } |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 899 | ++it; |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 900 | continue; |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 901 | } |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 902 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 903 | if ((key != worst) || |
| 904 | (worstPid && (element->getPid() != worstPid))) { |
Mark Salyzyn | fd318a8 | 2015-06-01 09:41:19 -0700 | [diff] [blame] | 905 | leading = false; |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 906 | last.clear(element); |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 907 | ++it; |
| 908 | continue; |
| 909 | } |
Mark Salyzyn | 1117818 | 2016-10-21 09:46:42 -0700 | [diff] [blame] | 910 | // key == worst below here |
| 911 | // If worstPid set, then element->getPid() == worstPid below here |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 912 | |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 913 | pruneRows--; |
| 914 | if (pruneRows == 0) { |
| 915 | break; |
| 916 | } |
| 917 | |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 918 | kick = true; |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 919 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 920 | unsigned short len = element->getMsgLen(); |
Mark Salyzyn | 65ec860 | 2015-05-22 10:03:31 -0700 | [diff] [blame] | 921 | |
| 922 | // do not create any leading drops |
| 923 | if (leading) { |
| 924 | it = erase(it); |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 925 | } else { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 926 | stats.drop(element); |
| 927 | element->setDropped(1); |
| 928 | if (last.coalesce(element, 1)) { |
Mark Salyzyn | 5c5189a | 2015-09-30 07:40:09 -0700 | [diff] [blame] | 929 | it = erase(it, true); |
Mark Salyzyn | 65ec860 | 2015-05-22 10:03:31 -0700 | [diff] [blame] | 930 | } else { |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 931 | last.add(element); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 932 | if (worstPid && |
| 933 | (!gc || (mLastWorstPidOfSystem[id].find(worstPid) == |
| 934 | mLastWorstPidOfSystem[id].end()))) { |
Mark Salyzyn | 1117818 | 2016-10-21 09:46:42 -0700 | [diff] [blame] | 935 | // element->getUid() may not be AID_SYSTEM, next best |
Mark Salyzyn | ab94771 | 2016-10-24 08:20:26 -0700 | [diff] [blame] | 936 | // watermark if current one empty. id is not |
| 937 | // LOG_ID_EVENTS or LOG_ID_SECURITY because of worstPid. |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 938 | mLastWorstPidOfSystem[id][worstPid] = it; |
| 939 | } |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 940 | if ((!gc && !worstPid) || |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 941 | (mLastWorst[id].find(worst) == mLastWorst[id].end())) { |
Mark Salyzyn | 6fa0d03 | 2016-07-14 15:34:30 -0700 | [diff] [blame] | 942 | mLastWorst[id][worst] = it; |
Mark Salyzyn | e2827d5 | 2015-09-08 09:12:51 -0700 | [diff] [blame] | 943 | } |
Mark Salyzyn | 65ec860 | 2015-05-22 10:03:31 -0700 | [diff] [blame] | 944 | ++it; |
| 945 | } |
Mark Salyzyn | a69d5a4 | 2015-03-16 12:04:09 -0700 | [diff] [blame] | 946 | } |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 947 | if (worst_sizes < second_worst_sizes) { |
| 948 | break; |
| 949 | } |
| 950 | worst_sizes -= len; |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 951 | } |
Mark Salyzyn | d84b27e | 2015-04-17 15:38:04 -0700 | [diff] [blame] | 952 | last.clear(); |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 953 | |
Mark Salyzyn | c402bc7 | 2014-04-01 17:19:47 -0700 | [diff] [blame] | 954 | if (!kick || !mPrune.worstUidEnabled()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 955 | break; // the following loop will ask bad clients to skip/drop |
Mark Salyzyn | 5c06ca4 | 2014-02-06 18:11:13 -0800 | [diff] [blame] | 956 | } |
| 957 | } |
| 958 | |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 959 | bool whitelist = false; |
Mark Salyzyn | c969086 | 2015-12-04 10:59:45 -0800 | [diff] [blame] | 960 | bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll; |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 961 | it = mLastSet[id] ? mLast[id] : mLogElements.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 962 | while ((pruneRows > 0) && (it != mLogElements.end())) { |
| 963 | LogBufferElement* element = *it; |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 964 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 965 | if (element->getLogId() != id) { |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 966 | it++; |
| 967 | continue; |
| 968 | } |
| 969 | |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 970 | if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { |
| 971 | mLast[id] = it; |
| 972 | mLastSet[id] = true; |
| 973 | } |
| 974 | |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 975 | if (oldest && (watermark <= element->getRealTime())) { |
Mark Salyzyn | 434f374 | 2017-05-11 13:28:33 -0700 | [diff] [blame] | 976 | busy = isBusy(watermark); |
| 977 | if (!whitelist && busy) kickMe(oldest, id, pruneRows); |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 978 | break; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 979 | } |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 980 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 981 | if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) { |
| 982 | // WhiteListed |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 983 | whitelist = true; |
| 984 | it++; |
| 985 | continue; |
| 986 | } |
| 987 | |
| 988 | it = erase(it); |
| 989 | pruneRows--; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 990 | } |
| 991 | |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 992 | // Do not save the whitelist if we are reader range limited |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 993 | if (whitelist && (pruneRows > 0)) { |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 994 | it = mLastSet[id] ? mLast[id] : mLogElements.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 995 | while ((it != mLogElements.end()) && (pruneRows > 0)) { |
| 996 | LogBufferElement* element = *it; |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 997 | |
Mark Salyzyn | edcbdfa | 2015-08-28 08:02:59 -0700 | [diff] [blame] | 998 | if (element->getLogId() != id) { |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 999 | ++it; |
| 1000 | continue; |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1001 | } |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 1002 | |
Mark Salyzyn | b7dd96e | 2016-01-11 10:58:09 -0800 | [diff] [blame] | 1003 | if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { |
| 1004 | mLast[id] = it; |
| 1005 | mLastSet[id] = true; |
| 1006 | } |
| 1007 | |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1008 | if (oldest && (watermark <= element->getRealTime())) { |
Mark Salyzyn | 434f374 | 2017-05-11 13:28:33 -0700 | [diff] [blame] | 1009 | busy = isBusy(watermark); |
| 1010 | if (busy) kickMe(oldest, id, pruneRows); |
Mark Salyzyn | 9cf5d40 | 2015-03-10 13:51:35 -0700 | [diff] [blame] | 1011 | break; |
| 1012 | } |
| 1013 | |
| 1014 | it = erase(it); |
| 1015 | pruneRows--; |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1016 | } |
| 1017 | } |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1018 | |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1019 | LogTimeEntry::unlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1020 | |
| 1021 | return (pruneRows > 0) && busy; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1022 | } |
| 1023 | |
| 1024 | // clear all rows of type "id" from the buffer. |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1025 | bool LogBuffer::clear(log_id_t id, uid_t uid) { |
| 1026 | bool busy = true; |
| 1027 | // If it takes more than 4 tries (seconds) to clear, then kill reader(s) |
| 1028 | for (int retry = 4;;) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 1029 | if (retry == 1) { // last pass |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1030 | // Check if it is still busy after the sleep, we say prune |
| 1031 | // one entry, not another clear run, so we are looking for |
| 1032 | // the quick side effect of the return value to tell us if |
| 1033 | // we have a _blocked_ reader. |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1034 | wrlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1035 | busy = prune(id, 1, uid); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1036 | unlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1037 | // It is still busy, blocked reader(s), lets kill them all! |
| 1038 | // otherwise, lets be a good citizen and preserve the slow |
| 1039 | // readers and let the clear run (below) deal with determining |
| 1040 | // if we are still blocked and return an error code to caller. |
| 1041 | if (busy) { |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1042 | LogTimeEntry::wrlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1043 | LastLogTimes::iterator times = mTimes.begin(); |
| 1044 | while (times != mTimes.end()) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 1045 | LogTimeEntry* entry = (*times); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1046 | // Killer punch |
| 1047 | if (entry->owned_Locked() && entry->isWatching(id)) { |
| 1048 | entry->release_Locked(); |
| 1049 | } |
| 1050 | times++; |
| 1051 | } |
| 1052 | LogTimeEntry::unlock(); |
| 1053 | } |
| 1054 | } |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1055 | wrlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1056 | busy = prune(id, ULONG_MAX, uid); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1057 | unlock(); |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1058 | if (!busy || !--retry) { |
| 1059 | break; |
| 1060 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 1061 | sleep(1); // Let reader(s) catch up after notification |
Mark Salyzyn | 8cf0d03 | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 1062 | } |
| 1063 | return busy; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1064 | } |
| 1065 | |
| 1066 | // get the used space associated with "id". |
| 1067 | unsigned long LogBuffer::getSizeUsed(log_id_t id) { |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1068 | rdlock(); |
Mark Salyzyn | d774bce | 2014-02-06 14:48:50 -0800 | [diff] [blame] | 1069 | size_t retval = stats.sizes(id); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1070 | unlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1071 | return retval; |
| 1072 | } |
| 1073 | |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1074 | // set the total space allocated to "id" |
| 1075 | int LogBuffer::setSize(log_id_t id, unsigned long size) { |
| 1076 | // Reasonable limits ... |
Mark Salyzyn | b004083 | 2016-09-27 13:08:23 -0700 | [diff] [blame] | 1077 | if (!__android_logger_valid_buffer_size(size)) { |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1078 | return -1; |
| 1079 | } |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1080 | wrlock(); |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1081 | log_buffer_size(id) = size; |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1082 | unlock(); |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1083 | return 0; |
| 1084 | } |
| 1085 | |
| 1086 | // get the total space allocated to "id" |
| 1087 | unsigned long LogBuffer::getSize(log_id_t id) { |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1088 | rdlock(); |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1089 | size_t retval = log_buffer_size(id); |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1090 | unlock(); |
Mark Salyzyn | c89839a | 2014-02-11 12:29:31 -0800 | [diff] [blame] | 1091 | return retval; |
| 1092 | } |
| 1093 | |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 1094 | log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, |
| 1095 | pid_t* lastTid, bool privileged, bool security, |
| 1096 | int (*filter)(const LogBufferElement* element, |
| 1097 | void* arg), |
| 1098 | void* arg) { |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1099 | LogBufferElementCollection::iterator it; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1100 | uid_t uid = reader->getUid(); |
| 1101 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1102 | rdlock(); |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1103 | |
Mark Salyzyn | d18255f | 2017-03-10 08:44:14 -0800 | [diff] [blame] | 1104 | if (start == log_time::EPOCH) { |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1105 | // client wants to start from the beginning |
| 1106 | it = mLogElements.begin(); |
| 1107 | } else { |
Mark Salyzyn | 9a3e8a4 | 2017-04-04 10:57:41 -0700 | [diff] [blame] | 1108 | // 3 second limit to continue search for out-of-order entries. |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1109 | log_time min = start - pruneMargin; |
| 1110 | |
Mark Salyzyn | 9a3e8a4 | 2017-04-04 10:57:41 -0700 | [diff] [blame] | 1111 | // Cap to 300 iterations we look back for out-of-order entries. |
| 1112 | size_t count = 300; |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1113 | |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1114 | // Client wants to start from some specified time. Chances are |
| 1115 | // we are better off starting from the end of the time sorted list. |
Mark Salyzyn | 782d4d2 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1116 | LogBufferElementCollection::iterator last; |
Mark Salyzyn | 46bd518 | 2017-03-27 13:12:41 -0700 | [diff] [blame] | 1117 | for (last = it = mLogElements.end(); it != mLogElements.begin(); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 1118 | /* do nothing */) { |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1119 | --it; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 1120 | LogBufferElement* element = *it; |
Mark Salyzyn | 242daa9 | 2017-03-10 10:31:48 -0800 | [diff] [blame] | 1121 | if (element->getRealTime() > start) { |
| 1122 | last = it; |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 1123 | } else if (element->getRealTime() == start) { |
| 1124 | last = ++it; |
| 1125 | break; |
Mark Salyzyn | 9a3e8a4 | 2017-04-04 10:57:41 -0700 | [diff] [blame] | 1126 | } else if (!--count || (element->getRealTime() < min)) { |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1127 | break; |
| 1128 | } |
| 1129 | } |
Mark Salyzyn | 242daa9 | 2017-03-10 10:31:48 -0800 | [diff] [blame] | 1130 | it = last; |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1131 | } |
| 1132 | |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 1133 | log_time curr = start; |
Mark Salyzyn | 1d7b071 | 2017-01-23 14:20:31 -0800 | [diff] [blame] | 1134 | |
Mark Salyzyn | 1b1f061 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1135 | LogBufferElement* lastElement = nullptr; // iterator corruption paranoia |
| 1136 | static const size_t maxSkip = 4194304; // maximum entries to skip |
| 1137 | size_t skip = maxSkip; |
Dragoslav Mitrinovic | 81624f2 | 2015-01-15 09:29:43 -0600 | [diff] [blame] | 1138 | for (; it != mLogElements.end(); ++it) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 1139 | LogBufferElement* element = *it; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1140 | |
Mark Salyzyn | 1b1f061 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1141 | if (!--skip) { |
| 1142 | android::prdebug("reader.per: too many elements skipped"); |
| 1143 | break; |
| 1144 | } |
| 1145 | if (element == lastElement) { |
| 1146 | android::prdebug("reader.per: identical elements"); |
| 1147 | break; |
| 1148 | } |
| 1149 | lastElement = element; |
| 1150 | |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1151 | if (!privileged && (element->getUid() != uid)) { |
| 1152 | continue; |
| 1153 | } |
| 1154 | |
Mark Salyzyn | b10f737 | 2016-01-26 14:32:35 -0800 | [diff] [blame] | 1155 | if (!security && (element->getLogId() == LOG_ID_SECURITY)) { |
| 1156 | continue; |
| 1157 | } |
| 1158 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1159 | // NB: calling out to another object with wrlock() held (safe) |
Mark Salyzyn | 0aaf6cd | 2015-03-03 13:39:37 -0800 | [diff] [blame] | 1160 | if (filter) { |
| 1161 | int ret = (*filter)(element, arg); |
| 1162 | if (ret == false) { |
| 1163 | continue; |
| 1164 | } |
| 1165 | if (ret != true) { |
| 1166 | break; |
| 1167 | } |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1168 | } |
| 1169 | |
Mark Salyzyn | bec7b2d | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 1170 | bool sameTid = false; |
| 1171 | if (lastTid) { |
| 1172 | sameTid = lastTid[element->getLogId()] == element->getTid(); |
| 1173 | // Dropped (chatty) immediately following a valid log from the |
| 1174 | // same source in the same log buffer indicates we have a |
| 1175 | // multiple identical squash. chatty that differs source |
| 1176 | // is due to spam filter. chatty to chatty of different |
| 1177 | // source is also due to spam filter. |
| 1178 | lastTid[element->getLogId()] = |
| 1179 | (element->getDropped() && !sameTid) ? 0 : element->getTid(); |
| 1180 | } |
Mark Salyzyn | 1d7b071 | 2017-01-23 14:20:31 -0800 | [diff] [blame] | 1181 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1182 | unlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1183 | |
| 1184 | // range locking in LastLogTimes looks after us |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 1185 | curr = element->flushTo(reader, this, privileged, sameTid); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1186 | |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 1187 | if (curr == element->FLUSH_ERROR) { |
| 1188 | return curr; |
Mark Salyzyn | e2c1ea4 | 2017-05-17 19:55:12 +0000 | [diff] [blame] | 1189 | } |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1190 | |
Mark Salyzyn | 1b1f061 | 2017-04-17 12:46:12 -0700 | [diff] [blame] | 1191 | skip = maxSkip; |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1192 | rdlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1193 | } |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1194 | unlock(); |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1195 | |
Mark Salyzyn | cb722de | 2017-05-18 10:06:00 -0700 | [diff] [blame^] | 1196 | return curr; |
Mark Salyzyn | 12bac90 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1197 | } |
Mark Salyzyn | d774bce | 2014-02-06 14:48:50 -0800 | [diff] [blame] | 1198 | |
Mark Salyzyn | 4a2fc1c | 2015-12-17 09:58:43 -0800 | [diff] [blame] | 1199 | std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid, |
| 1200 | unsigned int logMask) { |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1201 | wrlock(); |
Mark Salyzyn | d774bce | 2014-02-06 14:48:50 -0800 | [diff] [blame] | 1202 | |
Mark Salyzyn | 4a2fc1c | 2015-12-17 09:58:43 -0800 | [diff] [blame] | 1203 | std::string ret = stats.format(uid, pid, logMask); |
Mark Salyzyn | d774bce | 2014-02-06 14:48:50 -0800 | [diff] [blame] | 1204 | |
Mark Salyzyn | d2712b1 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 1205 | unlock(); |
Mark Salyzyn | 7c528d9 | 2015-08-20 10:01:44 -0700 | [diff] [blame] | 1206 | |
| 1207 | return ret; |
Mark Salyzyn | d774bce | 2014-02-06 14:48:50 -0800 | [diff] [blame] | 1208 | } |