Revert "logd: drop mSequence from LogBufferElement"
This reverts commit 5a34d6ea43d28f3b5d27bf6dd5b9fa31ec033531.
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
diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h
index ceaf393..a69d439 100644
--- a/logd/FlushCommand.h
+++ b/logd/FlushCommand.h
@@ -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;
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index f21b94c..5bec076 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -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 @@
}
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 @@
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 @@
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 @@
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 @@
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 @@
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
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 423b356..16225a5 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -118,11 +118,10 @@
// 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);
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index ec81933..3714800 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -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 @@
: 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 @@
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 @@
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 @@
}
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);
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index fd790e4..434b7db 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -39,6 +39,7 @@
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 @@
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);
};
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index d52d459..22178f1 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -129,70 +129,53 @@
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 @@
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;
}
diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
index 1723139..1d8d5fc 100644
--- a/logd/LogTimes.cpp
+++ b/logd/LogTimes.cpp
@@ -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 @@
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 @@
break;
}
- me->mStart = start + log_time(0, 1);
+ me->mStart = start + 1;
if (me->mNonBlock || me->mRelease) {
break;
@@ -157,7 +155,7 @@
}
if (me->mCount == 0) {
- me->mStart = element->getRealTime();
+ me->mStart = element->getSequence();
}
if ((!me->mPid || (me->mPid == element->getPid())) &&
@@ -176,7 +174,7 @@
LogTimeEntry::wrlock();
- me->mStart = element->getRealTime();
+ me->mStart = element->getSequence();
if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--;
diff --git a/logd/LogTimes.h b/logd/LogTimes.h
index 49b2d9d..0c1b36f 100644
--- a/logd/LogTimes.h
+++ b/logd/LogTimes.h
@@ -49,13 +49,12 @@
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;