Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 1 | /* |
| 2 | * Copyright (C) 2014 The Android Open Source Project |
| 3 | * |
| 4 | * Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | * you may not use this file except in compliance with the License. |
| 6 | * You may obtain a copy of the License at |
| 7 | * |
| 8 | * http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | * |
| 10 | * Unless required by applicable law or agreed to in writing, software |
| 11 | * distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | * See the License for the specific language governing permissions and |
| 14 | * limitations under the License. |
| 15 | */ |
| 16 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 17 | #include "LogReaderThread.h" |
| 18 | |
Mark Salyzyn | b75cce0 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 19 | #include <errno.h> |
Mark Salyzyn | ae2abf1 | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 20 | #include <string.h> |
Mark Salyzyn | 8daa9af | 2014-04-28 14:07:23 -0700 | [diff] [blame] | 21 | #include <sys/prctl.h> |
| 22 | |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 23 | #include "LogBuffer.h" |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 24 | #include "LogReader.h" |
| 25 | |
Tom Cherry | 320f596 | 2020-05-04 17:25:34 -0700 | [diff] [blame^] | 26 | using namespace std::placeholders; |
| 27 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 28 | pthread_mutex_t LogReaderThread::timesLock = PTHREAD_MUTEX_INITIALIZER; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 29 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 30 | LogReaderThread::LogReaderThread(LogReader& reader, SocketClient* client, bool non_block, |
| 31 | unsigned long tail, log_mask_t log_mask, pid_t pid, |
| 32 | log_time start_time, uint64_t start, uint64_t timeout, |
| 33 | bool privileged, bool can_read_security_logs) |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 34 | : leadingDropped(false), |
Mark Salyzyn | 501c373 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 35 | mReader(reader), |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 36 | mLogMask(log_mask), |
Mark Salyzyn | 501c373 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 37 | mPid(pid), |
| 38 | mCount(0), |
| 39 | mTail(tail), |
| 40 | mIndex(0), |
| 41 | mClient(client), |
Tom Cherry | 65ab7fe | 2019-08-21 14:53:06 -0700 | [diff] [blame] | 42 | mStartTime(start_time), |
Mark Salyzyn | 501c373 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 43 | mStart(start), |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 44 | mNonBlock(non_block), |
Tom Cherry | 79d54f7 | 2020-05-04 11:13:55 -0700 | [diff] [blame] | 45 | privileged_(privileged), |
| 46 | can_read_security_logs_(can_read_security_logs) { |
Mark Salyzyn | b75cce0 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 47 | mTimeout.tv_sec = timeout / NS_PER_SEC; |
| 48 | mTimeout.tv_nsec = timeout % NS_PER_SEC; |
Mark Salyzyn | ae2abf1 | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 49 | memset(mLastTid, 0, sizeof(mLastTid)); |
| 50 | pthread_cond_init(&threadTriggeredCondition, nullptr); |
Mark Salyzyn | 7718778 | 2015-05-12 15:21:31 -0700 | [diff] [blame] | 51 | cleanSkip_Locked(); |
Mark Salyzyn | a16f761 | 2014-08-07 08:16:52 -0700 | [diff] [blame] | 52 | } |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 53 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 54 | bool LogReaderThread::startReader_Locked() { |
Mark Salyzyn | 765f782 | 2014-04-04 12:47:44 -0700 | [diff] [blame] | 55 | pthread_attr_t attr; |
| 56 | |
Mark Salyzyn | 765f782 | 2014-04-04 12:47:44 -0700 | [diff] [blame] | 57 | if (!pthread_attr_init(&attr)) { |
| 58 | if (!pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED)) { |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 59 | if (!pthread_create(&mThread, &attr, LogReaderThread::threadStart, this)) { |
Mark Salyzyn | 765f782 | 2014-04-04 12:47:44 -0700 | [diff] [blame] | 60 | pthread_attr_destroy(&attr); |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 61 | return true; |
Mark Salyzyn | 765f782 | 2014-04-04 12:47:44 -0700 | [diff] [blame] | 62 | } |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 63 | } |
Mark Salyzyn | 765f782 | 2014-04-04 12:47:44 -0700 | [diff] [blame] | 64 | pthread_attr_destroy(&attr); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 65 | } |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 66 | |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 67 | return false; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 68 | } |
| 69 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 70 | void* LogReaderThread::threadStart(void* obj) { |
Mark Salyzyn | 8daa9af | 2014-04-28 14:07:23 -0700 | [diff] [blame] | 71 | prctl(PR_SET_NAME, "logd.reader.per"); |
| 72 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 73 | LogReaderThread* me = reinterpret_cast<LogReaderThread*>(obj); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 74 | |
Mark Salyzyn | 501c373 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 75 | SocketClient* client = me->mClient; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 76 | |
Mark Salyzyn | 501c373 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 77 | LogBuffer& logbuf = me->mReader.logbuf(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 78 | |
Mark Salyzyn | 047cc07 | 2015-06-04 13:35:30 -0700 | [diff] [blame] | 79 | me->leadingDropped = true; |
| 80 | |
Mark Salyzyn | 3c501b5 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 81 | wrlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 82 | |
Tom Cherry | 10d086e | 2019-08-21 14:16:34 -0700 | [diff] [blame] | 83 | uint64_t start = me->mStart; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 84 | |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 85 | while (!me->mRelease) { |
Mark Salyzyn | b75cce0 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 86 | if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) { |
Tom Cherry | c9fa42c | 2020-04-08 10:37:09 -0700 | [diff] [blame] | 87 | if (pthread_cond_clockwait(&me->threadTriggeredCondition, ×Lock, CLOCK_MONOTONIC, |
| 88 | &me->mTimeout) == ETIMEDOUT) { |
Mark Salyzyn | b75cce0 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 89 | me->mTimeout.tv_sec = 0; |
| 90 | me->mTimeout.tv_nsec = 0; |
| 91 | } |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 92 | if (me->mRelease) { |
Mark Salyzyn | b75cce0 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 93 | break; |
| 94 | } |
| 95 | } |
| 96 | |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 97 | unlock(); |
| 98 | |
| 99 | if (me->mTail) { |
Tom Cherry | 79d54f7 | 2020-05-04 11:13:55 -0700 | [diff] [blame] | 100 | logbuf.flushTo(client, start, nullptr, me->privileged_, me->can_read_security_logs_, |
Tom Cherry | 320f596 | 2020-05-04 17:25:34 -0700 | [diff] [blame^] | 101 | std::bind(&LogReaderThread::FilterFirstPass, _1, me)); |
Mark Salyzyn | 047cc07 | 2015-06-04 13:35:30 -0700 | [diff] [blame] | 102 | me->leadingDropped = true; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 103 | } |
Tom Cherry | 79d54f7 | 2020-05-04 11:13:55 -0700 | [diff] [blame] | 104 | start = logbuf.flushTo(client, start, me->mLastTid, me->privileged_, |
Tom Cherry | 320f596 | 2020-05-04 17:25:34 -0700 | [diff] [blame^] | 105 | me->can_read_security_logs_, |
| 106 | std::bind(&LogReaderThread::FilterSecondPass, _1, me)); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 107 | |
Tom Cherry | 65ab7fe | 2019-08-21 14:53:06 -0700 | [diff] [blame] | 108 | // We only ignore entries before the original start time for the first flushTo(), if we |
| 109 | // get entries after this first flush before the original start time, then the client |
| 110 | // wouldn't have seen them. |
| 111 | // Note: this is still racy and may skip out of order events that came in since the last |
| 112 | // time the client disconnected and then reconnected with the new start time. The long term |
| 113 | // solution here is that clients must request events since a specific sequence number. |
| 114 | me->mStartTime.tv_sec = 0; |
| 115 | me->mStartTime.tv_nsec = 0; |
| 116 | |
Mark Salyzyn | 3c501b5 | 2017-04-18 14:09:45 -0700 | [diff] [blame] | 117 | wrlock(); |
Mark Salyzyn | a16f761 | 2014-08-07 08:16:52 -0700 | [diff] [blame] | 118 | |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 119 | if (start == LogBufferElement::FLUSH_ERROR) { |
Mark Salyzyn | de4bb9c | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 120 | break; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 121 | } |
| 122 | |
Tom Cherry | 10d086e | 2019-08-21 14:16:34 -0700 | [diff] [blame] | 123 | me->mStart = start + 1; |
Mark Salyzyn | de4bb9c | 2015-09-16 15:34:00 -0700 | [diff] [blame] | 124 | |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 125 | if (me->mNonBlock || me->mRelease) { |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 126 | break; |
| 127 | } |
| 128 | |
TraianX Schiau | da6495d | 2014-12-17 10:53:41 +0200 | [diff] [blame] | 129 | me->cleanSkip_Locked(); |
| 130 | |
Mark Salyzyn | b75cce0 | 2015-11-30 11:35:56 -0800 | [diff] [blame] | 131 | if (!me->mTimeout.tv_sec && !me->mTimeout.tv_nsec) { |
| 132 | pthread_cond_wait(&me->threadTriggeredCondition, ×Lock); |
| 133 | } |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 134 | } |
| 135 | |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 136 | LogReader& reader = me->mReader; |
| 137 | reader.release(client); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 138 | |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 139 | client->decRef(); |
| 140 | |
| 141 | LastLogTimes& times = reader.logbuf().mTimes; |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 142 | auto it = std::find_if(times.begin(), times.end(), |
| 143 | [&me](const auto& other) { return other.get() == me; }); |
Tom Cherry | 4f22786 | 2018-10-08 17:33:50 -0700 | [diff] [blame] | 144 | |
| 145 | if (it != times.end()) { |
| 146 | times.erase(it); |
| 147 | } |
| 148 | |
| 149 | unlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 150 | |
Mark Salyzyn | ae2abf1 | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 151 | return nullptr; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 152 | } |
| 153 | |
| 154 | // A first pass to count the number of elements |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 155 | int LogReaderThread::FilterFirstPass(const LogBufferElement* element, void* obj) { |
| 156 | LogReaderThread* me = reinterpret_cast<LogReaderThread*>(obj); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 157 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 158 | LogReaderThread::wrlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 159 | |
Mark Salyzyn | 047cc07 | 2015-06-04 13:35:30 -0700 | [diff] [blame] | 160 | if (me->leadingDropped) { |
| 161 | if (element->getDropped()) { |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 162 | LogReaderThread::unlock(); |
Mark Salyzyn | 047cc07 | 2015-06-04 13:35:30 -0700 | [diff] [blame] | 163 | return false; |
| 164 | } |
| 165 | me->leadingDropped = false; |
| 166 | } |
| 167 | |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 168 | if (me->mCount == 0) { |
Tom Cherry | 10d086e | 2019-08-21 14:16:34 -0700 | [diff] [blame] | 169 | me->mStart = element->getSequence(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 170 | } |
| 171 | |
Tom Cherry | 65ab7fe | 2019-08-21 14:53:06 -0700 | [diff] [blame] | 172 | if ((!me->mPid || me->mPid == element->getPid()) && me->isWatching(element->getLogId()) && |
| 173 | (me->mStartTime == log_time::EPOCH || me->mStartTime <= element->getRealTime())) { |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 174 | ++me->mCount; |
| 175 | } |
| 176 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 177 | LogReaderThread::unlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 178 | |
| 179 | return false; |
| 180 | } |
| 181 | |
| 182 | // A second pass to send the selected elements |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 183 | int LogReaderThread::FilterSecondPass(const LogBufferElement* element, void* obj) { |
| 184 | LogReaderThread* me = reinterpret_cast<LogReaderThread*>(obj); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 185 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 186 | LogReaderThread::wrlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 187 | |
Tom Cherry | 10d086e | 2019-08-21 14:16:34 -0700 | [diff] [blame] | 188 | me->mStart = element->getSequence(); |
TraianX Schiau | da6495d | 2014-12-17 10:53:41 +0200 | [diff] [blame] | 189 | |
| 190 | if (me->skipAhead[element->getLogId()]) { |
| 191 | me->skipAhead[element->getLogId()]--; |
Mark Salyzyn | 8d7656b | 2014-06-05 15:58:43 -0700 | [diff] [blame] | 192 | goto skip; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 193 | } |
| 194 | |
Mark Salyzyn | 047cc07 | 2015-06-04 13:35:30 -0700 | [diff] [blame] | 195 | if (me->leadingDropped) { |
| 196 | if (element->getDropped()) { |
| 197 | goto skip; |
| 198 | } |
| 199 | me->leadingDropped = false; |
| 200 | } |
| 201 | |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 202 | // Truncate to close race between first and second pass |
| 203 | if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) { |
Mark Salyzyn | f7c0f75 | 2015-03-03 13:39:37 -0800 | [diff] [blame] | 204 | goto stop; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 205 | } |
| 206 | |
TraianX Schiau | da6495d | 2014-12-17 10:53:41 +0200 | [diff] [blame] | 207 | if (!me->isWatching(element->getLogId())) { |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 208 | goto skip; |
| 209 | } |
| 210 | |
| 211 | if (me->mPid && (me->mPid != element->getPid())) { |
| 212 | goto skip; |
| 213 | } |
| 214 | |
Tom Cherry | 65ab7fe | 2019-08-21 14:53:06 -0700 | [diff] [blame] | 215 | if (me->mStartTime != log_time::EPOCH && element->getRealTime() <= me->mStartTime) { |
| 216 | goto skip; |
| 217 | } |
| 218 | |
Jintao_Zhu | 5f93072 | 2018-11-11 03:13:24 -0800 | [diff] [blame] | 219 | if (me->mRelease) { |
| 220 | goto stop; |
| 221 | } |
| 222 | |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 223 | if (!me->mTail) { |
| 224 | goto ok; |
| 225 | } |
| 226 | |
| 227 | ++me->mIndex; |
| 228 | |
| 229 | if ((me->mCount > me->mTail) && (me->mIndex <= (me->mCount - me->mTail))) { |
| 230 | goto skip; |
| 231 | } |
| 232 | |
| 233 | if (!me->mNonBlock) { |
| 234 | me->mTail = 0; |
| 235 | } |
| 236 | |
| 237 | ok: |
TraianX Schiau | da6495d | 2014-12-17 10:53:41 +0200 | [diff] [blame] | 238 | if (!me->skipAhead[element->getLogId()]) { |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 239 | LogReaderThread::unlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 240 | return true; |
| 241 | } |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 242 | // FALLTHRU |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 243 | |
| 244 | skip: |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 245 | LogReaderThread::unlock(); |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 246 | return false; |
Mark Salyzyn | f7c0f75 | 2015-03-03 13:39:37 -0800 | [diff] [blame] | 247 | |
| 248 | stop: |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 249 | LogReaderThread::unlock(); |
Mark Salyzyn | f7c0f75 | 2015-03-03 13:39:37 -0800 | [diff] [blame] | 250 | return -1; |
Mark Salyzyn | 0175b07 | 2014-02-26 09:50:16 -0800 | [diff] [blame] | 251 | } |
TraianX Schiau | da6495d | 2014-12-17 10:53:41 +0200 | [diff] [blame] | 252 | |
Tom Cherry | 6ec71e9 | 2020-05-04 12:53:36 -0700 | [diff] [blame] | 253 | void LogReaderThread::cleanSkip_Locked(void) { |
Mark Salyzyn | ae2abf1 | 2017-03-31 10:48:39 -0700 | [diff] [blame] | 254 | memset(skipAhead, 0, sizeof(skipAhead)); |
TraianX Schiau | da6495d | 2014-12-17 10:53:41 +0200 | [diff] [blame] | 255 | } |