openkylin
/
platform_system_core
mirror of https://gitee.com/openkylin/platform_system_core.git
9
0
Fork 0
Code Issues Projects Releases Wiki Activity

Revert "logd: drop mSequence from LogBufferElement" 

This reverts commit 5a34d6ea43.

There is a long standing bug that logd will leak memory during its
prune process if the time on the device changes significantly forwards
then backwards.  This is due to using the timestamp of each log
message to determine what log messages are yet to be processed by a
reader thread.

Various attempts have been made to rectify this, but the only solution
that safely fixes this issue is to go back to using sequence numbers
on the log messages.

Bug: 64675203
Bug: 77971811
Bug: 149340579
Bug: 150923384
Test: logcat output looks sane
Change-Id: Ibce79cf184eb29a4914f3e42a8cb2868d04dc165
This commit is contained in:
Tom Cherry 2019-08-21 14:16:34 -07:00
parent 7514558b81
commit 10d086e26e
8 changed files with 78 additions and 104 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
logd/FlushCommand.h
View File

@ -16,7 +16,7 @@
#ifndef _FLUSH_COMMAND_H
#define _FLUSH_COMMAND_H
#include <private/android_logger.h>
#include <android/log.h>
#include <sysutils/SocketClientCommand.h>
class LogBufferElement;

42
logd/LogBuffer.cpp
View File

@ -27,6 +27,7 @@
#include <unistd.h>
#include <unordered_map>
#include <utility>
#include <cutils/properties.h>
#include <private/android_logger.h>
@ -560,12 +561,11 @@ class LogBufferElementLast {
}
void clear(LogBufferElement* element) {
log_time current =
element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0);
uint64_t current = element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC);
for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
LogBufferElement* mapElement = it->second;
if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) &&
(current > mapElement->getRealTime())) {
if (mapElement->getDropped() >= EXPIRE_THRESHOLD &&
current > mapElement->getRealTime().nsec()) {
it = map.erase(it);
} else {
++it;
@ -683,7 +683,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && oldest->mStart <= element->getSequence()) {
busy = true;
kickMe(oldest, id, pruneRows);
break;
@ -771,7 +771,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
while (it != mLogElements.end()) {
LogBufferElement* element = *it;
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && oldest->mStart <= element->getSequence()) {
busy = true;
// Do not let chatty eliding trigger any reader mitigation
break;
@ -923,7 +923,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && oldest->mStart <= element->getSequence()) {
busy = true;
if (!whitelist) kickMe(oldest, id, pruneRows);
break;
@ -956,7 +956,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && oldest->mStart <= element->getSequence()) {
busy = true;
kickMe(oldest, id, pruneRows);
break;
@ -1045,42 +1045,32 @@ unsigned long LogBuffer::getSize(log_id_t id) {
return retval;
}
log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
pid_t* lastTid, bool privileged, bool security,
int (*filter)(const LogBufferElement* element,
void* arg),
void* arg) {
uint64_t LogBuffer::flushTo(SocketClient* reader, uint64_t start, pid_t* lastTid, bool privileged,
bool security,
int (*filter)(const LogBufferElement* element, void* arg), void* arg) {
LogBufferElementCollection::iterator it;
uid_t uid = reader->getUid();
rdlock();
if (start == log_time::EPOCH) {
if (start <= 1) {
// client wants to start from the beginning
it = mLogElements.begin();
} else {
// Cap to 300 iterations we look back for out-of-order entries.
size_t count = 300;
// Client wants to start from some specified time. Chances are
// we are better off starting from the end of the time sorted list.
LogBufferElementCollection::iterator last;
for (last = it = mLogElements.end(); it != mLogElements.begin();
for (it = mLogElements.end(); it != mLogElements.begin();
/* do nothing */) {
--it;
LogBufferElement* element = *it;
if (element->getRealTime() > start) {
last = it;
} else if (element->getRealTime() == start) {
last = ++it;
break;
} else if (!--count) {
if (element->getSequence() <= start) {
it++;
break;
}
}
it = last;
}
log_time curr = start;
uint64_t curr = start;
LogBufferElement* lastElement = nullptr; // iterator corruption paranoia
static const size_t maxSkip = 4194304; // maximum entries to skip

5
logd/LogBuffer.h
View File

@ -118,11 +118,10 @@ class LogBuffer {
// lastTid is an optional context to help detect if the last previous
// valid message was from the same source so we can differentiate chatty
// filter types (identical or expired)
log_time flushTo(SocketClient* writer, const log_time& start,
uint64_t flushTo(SocketClient* writer, uint64_t start,
pid_t* lastTid, // &lastTid[LOG_ID_MAX] or nullptr
bool privileged, bool security,
int (*filter)(const LogBufferElement* element,
void* arg) = nullptr,
int (*filter)(const LogBufferElement* element, void* arg) = nullptr,
void* arg = nullptr);
bool clear(log_id_t id, uid_t uid = AID_ROOT);

17
logd/LogBufferElement.cpp
View File

@ -30,15 +30,15 @@
#include "LogReader.h"
#include "LogUtils.h"
const log_time LogBufferElement::FLUSH_ERROR((uint32_t)-1, (uint32_t)-1);
const uint64_t LogBufferElement::FLUSH_ERROR(0);
atomic_int_fast64_t LogBufferElement::sequence(1);
LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,
const char* msg, uint16_t len)
LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
pid_t tid, const char* msg, uint16_t len)
: mUid(uid),
mPid(pid),
mTid(tid),
mSequence(sequence.fetch_add(1, memory_order_relaxed)),
mRealTime(realtime),
mMsgLen(len),
mLogId(log_id),
@ -51,6 +51,7 @@ LogBufferElement::LogBufferElement(const LogBufferElement& elem)
: mUid(elem.mUid),
mPid(elem.mPid),
mTid(elem.mTid),
mSequence(elem.mSequence),
mRealTime(elem.mRealTime),
mMsgLen(elem.mMsgLen),
mLogId(elem.mLogId),
@ -244,7 +245,7 @@ size_t LogBufferElement::populateDroppedMessage(char*& buffer, LogBuffer* parent
return retval;
}
log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool lastSame) {
uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool lastSame) {
struct logger_entry entry = {};
entry.hdr_size = sizeof(struct logger_entry);
@ -263,7 +264,7 @@ log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool
if (mDropped) {
entry.len = populateDroppedMessage(buffer, parent, lastSame);
if (!entry.len) return mRealTime;
if (!entry.len) return mSequence;
iovec[1].iov_base = buffer;
} else {
entry.len = mMsgLen;
@ -271,9 +272,7 @@ log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool
}
iovec[1].iov_len = entry.len;
log_time retval = reader->sendDatav(iovec, 1 + (entry.len != 0))
? FLUSH_ERROR
: mRealTime;
uint64_t retval = reader->sendDatav(iovec, 1 + (entry.len != 0)) ? FLUSH_ERROR : mSequence;
if (buffer) free(buffer);

7
logd/LogBufferElement.h
View File

@ -39,6 +39,7 @@ class __attribute__((packed)) LogBufferElement {
const uint32_t mUid;
const uint32_t mPid;
const uint32_t mTid;
uint64_t mSequence;
log_time mRealTime;
union {
char* mMsg; // mDropped == false
@ -90,10 +91,12 @@ class __attribute__((packed)) LogBufferElement {
const char* getMsg() const {
return mDropped ? nullptr : mMsg;
}
uint64_t getSequence() const { return mSequence; }
static uint64_t getCurrentSequence() { return sequence.load(memory_order_relaxed); }
log_time getRealTime(void) const {
return mRealTime;
}
static const log_time FLUSH_ERROR;
log_time flushTo(SocketClient* writer, LogBuffer* parent, bool lastSame);
static const uint64_t FLUSH_ERROR;
uint64_t flushTo(SocketClient* writer, LogBuffer* parent, bool lastSame);
};

88
logd/LogReader.cpp
View File

@ -129,70 +129,53 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
nonBlock = true;
}
log_time sequence = start;
//
// This somewhat expensive data validation operation is required
// for non-blocking, with timeout. The incoming timestamp must be
// in range of the list, if not, return immediately. This is
// used to prevent us from from getting stuck in timeout processing
// with an invalid time.
//
// Find if time is really present in the logs, monotonic or real, implicit
// conversion from monotonic or real as necessary to perform the check.
// Exit in the check loop ASAP as you find a transition from older to
// newer, but use the last entry found to ensure overlap.
//
if (nonBlock && (sequence != log_time::EPOCH) && timeout) {
class LogFindStart { // A lambda by another name
private:
uint64_t sequence = 1;
// Convert realtime to sequence number
if (start != log_time::EPOCH) {
class LogFindStart {
const pid_t mPid;
const unsigned mLogMask;
bool mStartTimeSet;
log_time mStart;
log_time& mSequence;
log_time mLast;
bool mIsMonotonic;
bool startTimeSet;
log_time& start;
uint64_t& sequence;
uint64_t last;
bool isMonotonic;
public:
LogFindStart(pid_t pid, unsigned logMask, log_time& sequence,
public:
LogFindStart(unsigned logMask, pid_t pid, log_time& start, uint64_t& sequence,
bool isMonotonic)
: mPid(pid),
mLogMask(logMask),
mStartTimeSet(false),
mStart(sequence),
mSequence(sequence),
mLast(sequence),
mIsMonotonic(isMonotonic) {
}
startTimeSet(false),
start(start),
sequence(sequence),
last(sequence),
isMonotonic(isMonotonic) {}
static int callback(const LogBufferElement* element, void* obj) {
LogFindStart* me = reinterpret_cast<LogFindStart*>(obj);
if ((!me->mPid || (me->mPid == element->getPid())) &&
(me->mLogMask & (1 << element->getLogId()))) {
log_time real = element->getRealTime();
if (me->mStart == real) {
me->mSequence = real;
me->mStartTimeSet = true;
if (me->start == element->getRealTime()) {
me->sequence = element->getSequence();
me->startTimeSet = true;
return -1;
} else if (!me->mIsMonotonic || android::isMonotonic(real)) {
if (me->mStart < real) {
me->mSequence = me->mLast;
me->mStartTimeSet = true;
} else if (!me->isMonotonic || android::isMonotonic(element->getRealTime())) {
if (me->start < element->getRealTime()) {
me->sequence = me->last;
me->startTimeSet = true;
return -1;
}
me->mLast = real;
me->last = element->getSequence();
} else {
me->mLast = real;
me->last = element->getSequence();
}
}
return false;
}
bool found() {
return mStartTimeSet;
}
} logFindStart(pid, logMask, sequence,
bool found() { return startTimeSet; }
} logFindStart(logMask, pid, start, sequence,
logbuf().isMonotonic() && android::isMonotonic(start));
logbuf().flushTo(cli, sequence, nullptr, FlushCommand::hasReadLogs(cli),
@ -200,18 +183,21 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
logFindStart.callback, &logFindStart);
if (!logFindStart.found()) {
doSocketDelete(cli);
return false;
if (nonBlock) {
doSocketDelete(cli);
return false;
}
sequence = LogBufferElement::getCurrentSequence();
}
}
android::prdebug(
"logdr: UID=%d GID=%d PID=%d %c tail=%lu logMask=%x pid=%d "
"start=%" PRIu64 "ns timeout=%" PRIu64 "ns\n",
cli->getUid(), cli->getGid(), cli->getPid(), nonBlock ? 'n' : 'b', tail,
logMask, (int)pid, sequence.nsec(), timeout);
"logdr: UID=%d GID=%d PID=%d %c tail=%lu logMask=%x pid=%d "
"start=%" PRIu64 "ns timeout=%" PRIu64 "ns\n",
cli->getUid(), cli->getGid(), cli->getPid(), nonBlock ? 'n' : 'b', tail, logMask,
(int)pid, start.nsec(), timeout);
if (sequence == log_time::EPOCH) {
if (start == log_time::EPOCH) {
timeout = 0;
}

12
logd/LogTimes.cpp
View File

@ -18,8 +18,6 @@
#include <string.h>
#include <sys/prctl.h>
#include <private/android_logger.h>
#include "FlushCommand.h"
#include "LogBuffer.h"
#include "LogReader.h"
@ -28,7 +26,7 @@
pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
unsigned long tail, log_mask_t logMask, pid_t pid, log_time start,
unsigned long tail, log_mask_t logMask, pid_t pid, uint64_t start,
uint64_t timeout)
: leadingDropped(false),
mReader(reader),
@ -80,7 +78,7 @@ void* LogTimeEntry::threadStart(void* obj) {
wrlock();
log_time start = me->mStart;
uint64_t start = me->mStart;
while (!me->mRelease) {
if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
@ -110,7 +108,7 @@ void* LogTimeEntry::threadStart(void* obj) {
break;
}
me->mStart = start + log_time(0, 1);
me->mStart = start + 1;
if (me->mNonBlock || me->mRelease) {
break;
@ -157,7 +155,7 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement* element, void* obj) {
}
if (me->mCount == 0) {
me->mStart = element->getRealTime();
me->mStart = element->getSequence();
}
if ((!me->mPid || (me->mPid == element->getPid())) &&
@ -176,7 +174,7 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) {
LogTimeEntry::wrlock();
me->mStart = element->getRealTime();
me->mStart = element->getSequence();
if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--;

9
logd/LogTimes.h
View File

@ -49,13 +49,12 @@ class LogTimeEntry {
unsigned long mTail;
unsigned long mIndex;
public:
LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
unsigned long tail, log_mask_t logMask, pid_t pid,
log_time start, uint64_t timeout);
public:
LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, unsigned long tail,
log_mask_t logMask, pid_t pid, uint64_t start, uint64_t timeout);
SocketClient* mClient;
log_time mStart;
uint64_t mStart;
struct timespec mTimeout; // CLOCK_MONOTONIC based timeout used for log wrapping.
const bool mNonBlock;