1 /* 2 * Copyright (C) 2020 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 #include "SimpleLogBuffer.h" 18 19 #include <android-base/logging.h> 20 21 #include "LogBufferElement.h" 22 #include "LogSize.h" 23 SimpleLogBuffer(LogReaderList * reader_list,LogTags * tags,LogStatistics * stats)24 SimpleLogBuffer::SimpleLogBuffer(LogReaderList* reader_list, LogTags* tags, LogStatistics* stats) 25 : reader_list_(reader_list), tags_(tags), stats_(stats) { 26 Init(); 27 } 28 ~SimpleLogBuffer()29 SimpleLogBuffer::~SimpleLogBuffer() {} 30 Init()31 void SimpleLogBuffer::Init() { 32 log_id_for_each(i) { 33 if (!SetSize(i, GetBufferSizeFromProperties(i))) { 34 SetSize(i, kLogBufferMinSize); 35 } 36 } 37 38 // Release any sleeping reader threads to dump their current content. 39 auto lock = std::lock_guard{logd_lock}; 40 for (const auto& reader_thread : reader_list_->running_reader_threads()) { 41 reader_thread->TriggerReader(); 42 } 43 } 44 GetOldest(log_id_t log_id)45 std::list<LogBufferElement>::iterator SimpleLogBuffer::GetOldest(log_id_t log_id) { 46 auto it = logs_.begin(); 47 if (oldest_[log_id]) { 48 it = *oldest_[log_id]; 49 } 50 while (it != logs_.end() && it->log_id() != log_id) { 51 it++; 52 } 53 if (it != logs_.end()) { 54 oldest_[log_id] = it; 55 } 56 return it; 57 } 58 ShouldLog(log_id_t log_id,const char * msg,uint16_t len)59 bool SimpleLogBuffer::ShouldLog(log_id_t log_id, const char* msg, uint16_t len) { 60 if (log_id == LOG_ID_SECURITY) { 61 return true; 62 } 63 64 int prio = ANDROID_LOG_INFO; 65 const char* tag = nullptr; 66 size_t tag_len = 0; 67 if (IsBinary(log_id)) { 68 int32_t numeric_tag = MsgToTag(msg, len); 69 tag = tags_->tagToName(numeric_tag); 70 if (tag) { 71 tag_len = strlen(tag); 72 } 73 } else { 74 prio = *msg; 75 tag = msg + 1; 76 tag_len = strnlen(tag, len - 1); 77 } 78 return __android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE); 79 } 80 Log(log_id_t log_id,log_time realtime,uid_t uid,pid_t pid,pid_t tid,const char * msg,uint16_t len)81 int SimpleLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, 82 const char* msg, uint16_t len) { 83 if (!__android_log_id_is_valid(log_id)) { 84 return -EINVAL; 85 } 86 87 if (!ShouldLog(log_id, msg, len)) { 88 // Log traffic received to total 89 stats_->AddTotal(log_id, len); 90 return -EACCES; 91 } 92 93 // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns. 94 // This prevents any chance that an outside source can request an 95 // exact entry with time specified in ms or us precision. 96 if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec; 97 98 auto lock = std::lock_guard{logd_lock}; 99 auto sequence = sequence_.fetch_add(1, std::memory_order_relaxed); 100 LogInternal(LogBufferElement(log_id, realtime, uid, pid, tid, sequence, msg, len)); 101 return len; 102 } 103 LogInternal(LogBufferElement && elem)104 void SimpleLogBuffer::LogInternal(LogBufferElement&& elem) { 105 log_id_t log_id = elem.log_id(); 106 107 logs_.emplace_back(std::move(elem)); 108 stats_->Add(logs_.back().ToLogStatisticsElement()); 109 MaybePrune(log_id); 110 reader_list_->NotifyNewLog(1 << log_id); 111 } 112 CreateFlushToState(uint64_t start,LogMask log_mask)113 std::unique_ptr<FlushToState> SimpleLogBuffer::CreateFlushToState(uint64_t start, 114 LogMask log_mask) { 115 return std::make_unique<FlushToState>(start, log_mask); 116 } 117 FlushTo(LogWriter * writer,FlushToState & abstract_state,const std::function<FilterResult (log_id_t log_id,pid_t pid,uint64_t sequence,log_time realtime)> & filter)118 bool SimpleLogBuffer::FlushTo( 119 LogWriter* writer, FlushToState& abstract_state, 120 const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence, 121 log_time realtime)>& filter) { 122 auto& state = reinterpret_cast<FlushToState&>(abstract_state); 123 124 std::list<LogBufferElement>::iterator it; 125 if (state.start() <= 1) { 126 // client wants to start from the beginning 127 it = logs_.begin(); 128 } else { 129 // Client wants to start from some specified time. Chances are 130 // we are better off starting from the end of the time sorted list. 131 for (it = logs_.end(); it != logs_.begin(); 132 /* do nothing */) { 133 --it; 134 if (it->sequence() == state.start()) { 135 break; 136 } else if (it->sequence() < state.start()) { 137 it++; 138 break; 139 } 140 } 141 } 142 143 for (; it != logs_.end(); ++it) { 144 LogBufferElement& element = *it; 145 146 state.set_start(element.sequence()); 147 148 if (!writer->privileged() && element.uid() != writer->uid()) { 149 continue; 150 } 151 152 if (((1 << element.log_id()) & state.log_mask()) == 0) { 153 continue; 154 } 155 156 if (filter) { 157 FilterResult ret = 158 filter(element.log_id(), element.pid(), element.sequence(), element.realtime()); 159 if (ret == FilterResult::kSkip) { 160 continue; 161 } 162 if (ret == FilterResult::kStop) { 163 break; 164 } 165 } 166 167 logd_lock.unlock(); 168 // We never prune logs equal to or newer than any LogReaderThreads' `start` value, so the 169 // `element` pointer is safe here without the lock 170 if (!element.FlushTo(writer)) { 171 logd_lock.lock(); 172 return false; 173 } 174 logd_lock.lock(); 175 } 176 177 state.set_start(state.start() + 1); 178 return true; 179 } 180 Clear(log_id_t id,uid_t uid)181 bool SimpleLogBuffer::Clear(log_id_t id, uid_t uid) { 182 // Try three times to clear, then disconnect the readers and try one final time. 183 for (int retry = 0; retry < 3; ++retry) { 184 { 185 auto lock = std::lock_guard{logd_lock}; 186 if (Prune(id, ULONG_MAX, uid)) { 187 return true; 188 } 189 } 190 sleep(1); 191 } 192 // Check if it is still busy after the sleep, we try to prune one entry, not another clear run, 193 // so we are looking for the quick side effect of the return value to tell us if we have a 194 // _blocked_ reader. 195 bool busy = false; 196 { 197 auto lock = std::lock_guard{logd_lock}; 198 busy = !Prune(id, 1, uid); 199 } 200 // It is still busy, disconnect all readers. 201 if (busy) { 202 auto lock = std::lock_guard{logd_lock}; 203 for (const auto& reader_thread : reader_list_->running_reader_threads()) { 204 if (reader_thread->IsWatching(id)) { 205 LOG(WARNING) << "Kicking blocked reader, " << reader_thread->name() 206 << ", from LogBuffer::clear()"; 207 reader_thread->Release(); 208 } 209 } 210 } 211 auto lock = std::lock_guard{logd_lock}; 212 return Prune(id, ULONG_MAX, uid); 213 } 214 215 // get the total space allocated to "id" GetSize(log_id_t id)216 size_t SimpleLogBuffer::GetSize(log_id_t id) { 217 auto lock = std::lock_guard{logd_lock}; 218 size_t retval = max_size_[id]; 219 return retval; 220 } 221 222 // set the total space allocated to "id" SetSize(log_id_t id,size_t size)223 bool SimpleLogBuffer::SetSize(log_id_t id, size_t size) { 224 // Reasonable limits ... 225 if (!IsValidBufferSize(size)) { 226 return false; 227 } 228 229 auto lock = std::lock_guard{logd_lock}; 230 max_size_[id] = size; 231 return true; 232 } 233 MaybePrune(log_id_t id)234 void SimpleLogBuffer::MaybePrune(log_id_t id) { 235 unsigned long prune_rows; 236 if (stats_->ShouldPrune(id, max_size_[id], &prune_rows)) { 237 Prune(id, prune_rows, 0); 238 } 239 } 240 Prune(log_id_t id,unsigned long prune_rows,uid_t caller_uid)241 bool SimpleLogBuffer::Prune(log_id_t id, unsigned long prune_rows, uid_t caller_uid) { 242 // Don't prune logs that are newer than the point at which any reader threads are reading from. 243 LogReaderThread* oldest = nullptr; 244 for (const auto& reader_thread : reader_list_->running_reader_threads()) { 245 if (!reader_thread->IsWatching(id)) { 246 continue; 247 } 248 if (!oldest || oldest->start() > reader_thread->start() || 249 (oldest->start() == reader_thread->start() && 250 reader_thread->deadline().time_since_epoch().count() != 0)) { 251 oldest = reader_thread.get(); 252 } 253 } 254 255 auto it = GetOldest(id); 256 257 while (it != logs_.end()) { 258 LogBufferElement& element = *it; 259 260 if (element.log_id() != id) { 261 ++it; 262 continue; 263 } 264 265 if (caller_uid != 0 && element.uid() != caller_uid) { 266 ++it; 267 continue; 268 } 269 270 if (oldest && oldest->start() <= element.sequence()) { 271 KickReader(oldest, id, prune_rows); 272 return false; 273 } 274 275 stats_->Subtract(element.ToLogStatisticsElement()); 276 it = Erase(it); 277 if (--prune_rows == 0) { 278 return true; 279 } 280 } 281 return true; 282 } 283 Erase(std::list<LogBufferElement>::iterator it)284 std::list<LogBufferElement>::iterator SimpleLogBuffer::Erase( 285 std::list<LogBufferElement>::iterator it) { 286 bool oldest_is_it[LOG_ID_MAX]; 287 log_id_for_each(i) { oldest_is_it[i] = oldest_[i] && it == *oldest_[i]; } 288 289 it = logs_.erase(it); 290 291 log_id_for_each(i) { 292 if (oldest_is_it[i]) { 293 if (__predict_false(it == logs_.end())) { 294 oldest_[i] = std::nullopt; 295 } else { 296 oldest_[i] = it; // Store the next iterator even if it does not correspond to 297 // the same log_id, as a starting point for GetOldest(). 298 } 299 } 300 } 301 302 return it; 303 } 304 305 // If the selected reader is blocking our pruning progress, decide on 306 // what kind of mitigation is necessary to unblock the situation. KickReader(LogReaderThread * reader,log_id_t id,unsigned long prune_rows)307 void SimpleLogBuffer::KickReader(LogReaderThread* reader, log_id_t id, unsigned long prune_rows) { 308 if (stats_->Sizes(id) > (2 * max_size_[id])) { // +100% 309 // A misbehaving or slow reader has its connection 310 // dropped if we hit too much memory pressure. 311 LOG(WARNING) << "Kicking blocked reader, " << reader->name() 312 << ", from LogBuffer::kickMe()"; 313 reader->Release(); 314 } else if (reader->deadline().time_since_epoch().count() != 0) { 315 // Allow a blocked WRAP deadline reader to trigger and start reporting the log data. 316 reader->TriggerReader(); 317 } else { 318 // tell slow reader to skip entries to catch up 319 LOG(WARNING) << "Skipping " << prune_rows << " entries from slow reader, " << reader->name() 320 << ", from LogBuffer::kickMe()"; 321 reader->TriggerSkip(id, prune_rows); 322 } 323 } 324