ACPR/android_system_core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Merge changes I2a073293,Ia55ef8b9,I79a385fc

Browse source 
am: 82b5c619b8

Change-Id: Iec41ebf6c7cd0ade134e622e9dfec483491f9e9c
This commit is contained in:
Mark Salyzyn 2017-03-16 17:14:18 +00:00 • committed by android-build-merger
commit 5a0afe7d27
9 changed files with 101 additions and 90 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
logd/FlushCommand.cpp
View file

@ -27,7 +27,7 @@
#include "LogUtils.h" #include "LogUtils.h"
FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail, FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid, uint64_t start, unsigned int logMask, pid_t pid, log_time start,
uint64_t timeout) uint64_t timeout)
: mReader(reader), : mReader(reader),
mNonBlock(nonBlock), mNonBlock(nonBlock),
@ -35,7 +35,7 @@ FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail,
mLogMask(logMask), mLogMask(logMask),
mPid(pid), mPid(pid),
mStart(start), mStart(start),
mTimeout((start > 1) ? timeout : 0) { mTimeout((start != log_time::EPOCH) ? timeout : 0) {
} }
// runSocketCommand is called once for every open client on the // runSocketCommand is called once for every open client on the

6
logd/FlushCommand.h
View file

@ -16,7 +16,7 @@
#ifndef _FLUSH_COMMAND_H #ifndef _FLUSH_COMMAND_H
#define _FLUSH_COMMAND_H #define _FLUSH_COMMAND_H
#include <android/log.h> #include <private/android_logger.h>
#include <sysutils/SocketClientCommand.h> #include <sysutils/SocketClientCommand.h>
class LogBufferElement; class LogBufferElement;
@ -31,13 +31,13 @@ class FlushCommand : public SocketClientCommand {
unsigned long mTail; unsigned long mTail;
unsigned int mLogMask; unsigned int mLogMask;
pid_t mPid; pid_t mPid;
uint64_t mStart; log_time mStart;
uint64_t mTimeout; uint64_t mTimeout;
public: public:
explicit FlushCommand(LogReader& mReader, bool nonBlock = false, explicit FlushCommand(LogReader& mReader, bool nonBlock = false,
unsigned long tail = -1, unsigned int logMask = -1, unsigned long tail = -1, unsigned int logMask = -1,
pid_t pid = 0, uint64_t start = 1, pid_t pid = 0, log_time start = log_time::EPOCH,
uint64_t timeout = 0); uint64_t timeout = 0);
virtual void runSocketCommand(SocketClient* client); virtual void runSocketCommand(SocketClient* client);

62
logd/LogBuffer.cpp
View file

@ -181,7 +181,7 @@ static enum match_type identical(LogBufferElement* elem,
lenr -= avcr - msgr; lenr -= avcr - msgr;
if (lenl != lenr) return DIFFERENT; if (lenl != lenr) return DIFFERENT;
// TODO: After b/35468874 is addressed, revisit "lenl > strlen(avc)" // TODO: After b/35468874 is addressed, revisit "lenl > strlen(avc)"
// condition, it might become superflous. // condition, it might become superfluous.
if (lenl > strlen(avc) && if (lenl > strlen(avc) &&
fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc),
lenl - strlen(avc))) { lenl - strlen(avc))) {
@ -374,18 +374,12 @@ void LogBuffer::log(LogBufferElement* elem) {
// NB: if end is region locked, place element at end of list // NB: if end is region locked, place element at end of list
LogBufferElementCollection::iterator it = mLogElements.end(); LogBufferElementCollection::iterator it = mLogElements.end();
LogBufferElementCollection::iterator last = it; LogBufferElementCollection::iterator last = it;
while (last != mLogElements.begin()) { if (__predict_true(it != mLogElements.begin())) --it;
--it; if (__predict_false(it == mLogElements.begin()) ||
if ((*it)->getRealTime() <= elem->getRealTime()) { __predict_true((*it)->getRealTime() <= elem->getRealTime())) {
break;
}
last = it;
}
if (last == mLogElements.end()) {
mLogElements.push_back(elem); mLogElements.push_back(elem);
} else { } else {
uint64_t end = 1; log_time end = log_time::EPOCH;
bool end_set = false; bool end_set = false;
bool end_always = false; bool end_always = false;
@ -399,6 +393,7 @@ void LogBuffer::log(LogBufferElement* elem) {
end_always = true; end_always = true;
break; break;
} }
// it passing mEnd is blocked by the following checks.
if (!end_set || (end <= entry->mEnd)) { if (!end_set || (end <= entry->mEnd)) {
end = entry->mEnd; end = entry->mEnd;
end_set = true; end_set = true;
@ -407,12 +402,20 @@ void LogBuffer::log(LogBufferElement* elem) {
times++; times++;
} }
if (end_always || (end_set && (end >= (*last)->getSequence()))) { if (end_always || (end_set && (end > (*it)->getRealTime()))) {
mLogElements.push_back(elem); mLogElements.push_back(elem);
} else { } else {
// should be short as timestamps are localized near end()
do {
last = it;
if (__predict_false(it == mLogElements.begin())) {
break;
}
--it;
} while (((*it)->getRealTime() > elem->getRealTime()) &&
(!end_set || (end <= (*it)->getRealTime())));
mLogElements.insert(last, elem); mLogElements.insert(last, elem);
} }
LogTimeEntry::unlock(); LogTimeEntry::unlock();
} }
@ -587,12 +590,12 @@ class LogBufferElementLast {
} }
void clear(LogBufferElement* element) { void clear(LogBufferElement* element) {
uint64_t current = log_time current =
element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC); element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0);
for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) { for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
LogBufferElement* mapElement = it->second; LogBufferElement* mapElement = it->second;
if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) && if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) &&
(current > mapElement->getRealTime().nsec())) { (current > mapElement->getRealTime())) {
it = map.erase(it); it = map.erase(it);
} else { } else {
++it; ++it;
@ -688,7 +691,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true; mLastSet[id] = true;
} }
if (oldest && (oldest->mStart <= element->getSequence())) { if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true; busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked(); oldest->triggerReader_Locked();
@ -780,7 +783,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
while (it != mLogElements.end()) { while (it != mLogElements.end()) {
LogBufferElement* element = *it; LogBufferElement* element = *it;
if (oldest && (oldest->mStart <= element->getSequence())) { if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true; busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked(); oldest->triggerReader_Locked();
@ -934,7 +937,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true; mLastSet[id] = true;
} }
if (oldest && (oldest->mStart <= element->getSequence())) { if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true; busy = true;
if (whitelist) { if (whitelist) {
break; break;
@ -978,7 +981,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true; mLastSet[id] = true;
} }
if (oldest && (oldest->mStart <= element->getSequence())) { if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true; busy = true;
if (stats.sizes(id) > (2 * log_buffer_size(id))) { if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island // kick a misbehaving log reader client off the island
@ -1071,32 +1074,37 @@ unsigned long LogBuffer::getSize(log_id_t id) {
return retval; return retval;
} }
uint64_t LogBuffer::flushTo( log_time LogBuffer::flushTo(
SocketClient* reader, const uint64_t start, bool privileged, bool security, SocketClient* reader, const log_time& start, bool privileged, bool security,
int (*filter)(const LogBufferElement* element, void* arg), void* arg) { int (*filter)(const LogBufferElement* element, void* arg), void* arg) {
LogBufferElementCollection::iterator it; LogBufferElementCollection::iterator it;
uint64_t max = start;
uid_t uid = reader->getUid(); uid_t uid = reader->getUid();
pthread_mutex_lock(&mLogElementsLock); pthread_mutex_lock(&mLogElementsLock);
if (start <= 1) { if (start == log_time::EPOCH) {
// client wants to start from the beginning // client wants to start from the beginning
it = mLogElements.begin(); it = mLogElements.begin();
} else { } else {
LogBufferElementCollection::iterator last = mLogElements.begin();
// 30 second limit to continue search for out-of-order entries.
log_time min = start - log_time(30, 0);
// Client wants to start from some specified time. Chances are // Client wants to start from some specified time. Chances are
// we are better off starting from the end of the time sorted list. // we are better off starting from the end of the time sorted list.
for (it = mLogElements.end(); it != mLogElements.begin(); for (it = mLogElements.end(); it != mLogElements.begin();
/* do nothing */) { /* do nothing */) {
--it; --it;
LogBufferElement* element = *it; LogBufferElement* element = *it;
if (element->getSequence() <= start) { if (element->getRealTime() > start) {
it++; last = it;
} else if (element->getRealTime() < min) {
break; break;
} }
} }
it = last;
} }
log_time max = start;
// Help detect if the valid message before is from the same source so // Help detect if the valid message before is from the same source so
// we can differentiate chatty filter types. // we can differentiate chatty filter types.
pid_t lastTid[LOG_ID_MAX] = { 0 }; pid_t lastTid[LOG_ID_MAX] = { 0 };
@ -1112,7 +1120,7 @@ uint64_t LogBuffer::flushTo(
continue; continue;
} }
if (element->getSequence() <= start) { if (element->getRealTime() <= start) {
continue; continue;
} }

2
logd/LogBuffer.h
View file

@ -115,7 +115,7 @@ class LogBuffer {
int log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, int log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
const char* msg, unsigned short len); const char* msg, unsigned short len);
uint64_t flushTo(SocketClient* writer, const uint64_t start, log_time flushTo(SocketClient* writer, const log_time& start,
bool privileged, bool security, bool privileged, bool security,
int (*filter)(const LogBufferElement* element, int (*filter)(const LogBufferElement* element,
void* arg) = NULL, void* arg) = NULL,

10
logd/LogBufferElement.cpp
View file

@ -30,7 +30,7 @@
#include "LogReader.h" #include "LogReader.h"
#include "LogUtils.h" #include "LogUtils.h"
const uint64_t LogBufferElement::FLUSH_ERROR(0); const log_time LogBufferElement::FLUSH_ERROR((uint32_t)-1, (uint32_t)-1);
atomic_int_fast64_t LogBufferElement::sequence(1); atomic_int_fast64_t LogBufferElement::sequence(1);
LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
@ -39,7 +39,6 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
: mUid(uid), : mUid(uid),
mPid(pid), mPid(pid),
mTid(tid), mTid(tid),
mSequence(sequence.fetch_add(1, memory_order_relaxed)),
mRealTime(realtime), mRealTime(realtime),
mMsgLen(len), mMsgLen(len),
mLogId(log_id) { mLogId(log_id) {
@ -55,7 +54,6 @@ LogBufferElement::LogBufferElement(const LogBufferElement& elem)
mUid(elem.mUid), mUid(elem.mUid),
mPid(elem.mPid), mPid(elem.mPid),
mTid(elem.mTid), mTid(elem.mTid),
mSequence(elem.mSequence),
mRealTime(elem.mRealTime), mRealTime(elem.mRealTime),
mMsgLen(elem.mMsgLen), mMsgLen(elem.mMsgLen),
mLogId(elem.mLogId) { mLogId(elem.mLogId) {
@ -206,7 +204,7 @@ size_t LogBufferElement::populateDroppedMessage(char*& buffer, LogBuffer* parent
return retval; return retval;
} }
uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
bool privileged, bool lastSame) { bool privileged, bool lastSame) {
struct logger_entry_v4 entry; struct logger_entry_v4 entry;
@ -229,7 +227,7 @@ uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
if (!mMsg) { if (!mMsg) {
entry.len = populateDroppedMessage(buffer, parent, lastSame); entry.len = populateDroppedMessage(buffer, parent, lastSame);
if (!entry.len) return mSequence; if (!entry.len) return mRealTime;
iovec[1].iov_base = buffer; iovec[1].iov_base = buffer;
} else { } else {
entry.len = mMsgLen; entry.len = mMsgLen;
@ -237,7 +235,7 @@ uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
} }
iovec[1].iov_len = entry.len; iovec[1].iov_len = entry.len;
uint64_t retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mSequence; log_time retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mRealTime;
if (buffer) free(buffer); if (buffer) free(buffer);

11
logd/LogBufferElement.h
View file

@ -40,7 +40,6 @@ class LogBufferElement {
const uint32_t mUid; const uint32_t mUid;
const uint32_t mPid; const uint32_t mPid;
const uint32_t mTid; const uint32_t mTid;
const uint64_t mSequence;
log_time mRealTime; log_time mRealTime;
char* mMsg; char* mMsg;
union { union {
@ -96,18 +95,12 @@ class LogBufferElement {
const char* getMsg() const { const char* getMsg() const {
return mMsg; return mMsg;
} }
uint64_t getSequence(void) const {
return mSequence;
}
static uint64_t getCurrentSequence(void) {
return sequence.load(memory_order_relaxed);
}
log_time getRealTime(void) const { log_time getRealTime(void) const {
return mRealTime; return mRealTime;
} }
static const uint64_t FLUSH_ERROR; static const log_time FLUSH_ERROR;
uint64_t flushTo(SocketClient* writer, LogBuffer* parent, bool privileged, log_time flushTo(SocketClient* writer, LogBuffer* parent, bool privileged,
bool lastSame); bool lastSame);
}; };

76
logd/LogReader.cpp
View file

@ -116,57 +116,70 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
nonBlock = true; nonBlock = true;
} }
uint64_t sequence = 1; log_time sequence = start;
// Convert realtime to sequence number //
if (start != log_time::EPOCH) { // This somewhat expensive data validation operation is required
class LogFindStart { // 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:
const pid_t mPid; const pid_t mPid;
const unsigned mLogMask; const unsigned mLogMask;
bool startTimeSet; bool mStartTimeSet;
log_time& start; log_time mStart;
uint64_t& sequence; log_time& mSequence;
uint64_t last; log_time mLast;
bool isMonotonic; bool mIsMonotonic;
public: public:
LogFindStart(unsigned logMask, pid_t pid, log_time& start, LogFindStart(pid_t pid, unsigned logMask, log_time& sequence,
uint64_t& sequence, bool isMonotonic) bool isMonotonic)
: mPid(pid), : mPid(pid),
mLogMask(logMask), mLogMask(logMask),
startTimeSet(false), mStartTimeSet(false),
start(start), mStart(sequence),
sequence(sequence), mSequence(sequence),
last(sequence), mLast(sequence),
isMonotonic(isMonotonic) { mIsMonotonic(isMonotonic) {
} }
static int callback(const LogBufferElement* element, void* obj) { static int callback(const LogBufferElement* element, void* obj) {
LogFindStart* me = reinterpret_cast<LogFindStart*>(obj); LogFindStart* me = reinterpret_cast<LogFindStart*>(obj);
if ((!me->mPid || (me->mPid == element->getPid())) && if ((!me->mPid || (me->mPid == element->getPid())) &&
(me->mLogMask & (1 << element->getLogId()))) { (me->mLogMask & (1 << element->getLogId()))) {
if (me->start == element->getRealTime()) { log_time real = element->getRealTime();
me->sequence = element->getSequence(); if (me->mStart == real) {
me->startTimeSet = true; me->mSequence = real;
me->mStartTimeSet = true;
return -1; return -1;
} else if (!me->isMonotonic || } else if (!me->mIsMonotonic || android::isMonotonic(real)) {
android::isMonotonic(element->getRealTime())) { if (me->mStart < real) {
if (me->start < element->getRealTime()) { me->mSequence = me->mLast;
me->sequence = me->last; me->mStartTimeSet = true;
me->startTimeSet = true;
return -1; return -1;
} }
me->last = element->getSequence(); me->mLast = real;
} else { } else {
me->last = element->getSequence(); me->mLast = real;
} }
} }
return false; return false;
} }
bool found() { bool found() {
return startTimeSet; return mStartTimeSet;
} }
} logFindStart(logMask, pid, start, sequence,
} logFindStart(pid, logMask, sequence,
logbuf().isMonotonic() && android::isMonotonic(start)); logbuf().isMonotonic() && android::isMonotonic(start));
logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli), logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli),
@ -174,11 +187,8 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
logFindStart.callback, &logFindStart); logFindStart.callback, &logFindStart);
if (!logFindStart.found()) { if (!logFindStart.found()) {
if (nonBlock) { doSocketDelete(cli);
doSocketDelete(cli); return false;
return false;
}
sequence = LogBufferElement::getCurrentSequence();
} }
} }

14
logd/LogTimes.cpp
View file

@ -17,6 +17,8 @@
#include <errno.h> #include <errno.h>
#include <sys/prctl.h> #include <sys/prctl.h>
#include <private/android_logger.h>
#include "FlushCommand.h" #include "FlushCommand.h"
#include "LogBuffer.h" #include "LogBuffer.h"
#include "LogReader.h" #include "LogReader.h"
@ -26,7 +28,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client,
bool nonBlock, unsigned long tail, bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid, uint64_t start, unsigned int logMask, pid_t pid, log_time start,
uint64_t timeout) uint64_t timeout)
: mRefCount(1), : mRefCount(1),
mRelease(false), mRelease(false),
@ -42,7 +44,7 @@ LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client,
mClient(client), mClient(client),
mStart(start), mStart(start),
mNonBlock(nonBlock), mNonBlock(nonBlock),
mEnd(LogBufferElement::getCurrentSequence()) { mEnd(log_time(android_log_clockid())) {
mTimeout.tv_sec = timeout / NS_PER_SEC; mTimeout.tv_sec = timeout / NS_PER_SEC;
mTimeout.tv_nsec = timeout % NS_PER_SEC; mTimeout.tv_nsec = timeout % NS_PER_SEC;
pthread_cond_init(&threadTriggeredCondition, NULL); pthread_cond_init(&threadTriggeredCondition, NULL);
@ -132,7 +134,7 @@ void* LogTimeEntry::threadStart(void* obj) {
lock(); lock();
uint64_t start = me->mStart; log_time start = me->mStart;
while (me->threadRunning && !me->isError_Locked()) { while (me->threadRunning && !me->isError_Locked()) {
if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) { if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
@ -163,7 +165,7 @@ void* LogTimeEntry::threadStart(void* obj) {
break; break;
} }
me->mStart = start + 1; me->mStart = start + log_time(0, 1);
if (me->mNonBlock || !me->threadRunning || me->isError_Locked()) { if (me->mNonBlock || !me->threadRunning || me->isError_Locked()) {
break; break;
@ -198,7 +200,7 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement* element, void* obj) {
} }
if (me->mCount == 0) { if (me->mCount == 0) {
me->mStart = element->getSequence(); me->mStart = element->getRealTime();
} }
if ((!me->mPid || (me->mPid == element->getPid())) && if ((!me->mPid || (me->mPid == element->getPid())) &&
@ -217,7 +219,7 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) {
LogTimeEntry::lock(); LogTimeEntry::lock();
me->mStart = element->getSequence(); me->mStart = element->getRealTime();
if (me->skipAhead[element->getLogId()]) { if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--; me->skipAhead[element->getLogId()]--;

6
logd/LogTimes.h
View file

@ -51,13 +51,13 @@ class LogTimeEntry {
public: public:
LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
unsigned long tail, unsigned int logMask, pid_t pid, unsigned long tail, unsigned int logMask, pid_t pid,
uint64_t start, uint64_t timeout); log_time start, uint64_t timeout);
SocketClient* mClient; SocketClient* mClient;
uint64_t mStart; log_time mStart;
struct timespec mTimeout; struct timespec mTimeout;
const bool mNonBlock; const bool mNonBlock;
const uint64_t mEnd; // only relevant if mNonBlock const log_time mEnd; // only relevant if mNonBlock
// Protect List manipulations // Protect List manipulations
static void lock(void) { static void lock(void) {