Merge changes Icc984f40,Ie4c46bc9,I0f238985,I63a729d2,I2b5900a2

* changes:
  logd: clearAll by UID speedup
  logd: clear return and deal with busy if readers locked
  logd: update region lock after entry has passed to reader socket
  logcat: do not exit buffer loop on error
  logd: clientHasLogCredentials false negatives
This commit is contained in:
Mark Salyzyn 2015-10-08 14:22:03 +00:00 committed by Gerrit Code Review
commit df345a8aac
6 changed files with 176 additions and 101 deletions

View file

@ -832,49 +832,66 @@ int main(int argc, char **argv)
} else {
logger_list = android_logger_list_alloc(mode, tail_lines, 0);
}
const char *openDeviceFail = NULL;
const char *clearFail = NULL;
const char *setSizeFail = NULL;
const char *getSizeFail = NULL;
// We have three orthogonal actions below to clear, set log size and
// get log size. All sharing the same iteration loop.
while (dev) {
dev->logger_list = logger_list;
dev->logger = android_logger_open(logger_list,
android_name_to_log_id(dev->device));
if (!dev->logger) {
logcat_panic(false, "Unable to open log device '%s'\n",
dev->device);
openDeviceFail = openDeviceFail ?: dev->device;
dev = dev->next;
continue;
}
if (clearLog) {
int ret;
ret = android_logger_clear(dev->logger);
if (ret) {
logcat_panic(false, "failed to clear the log");
if (android_logger_clear(dev->logger)) {
clearFail = clearFail ?: dev->device;
}
}
if (setLogSize && android_logger_set_log_size(dev->logger, setLogSize)) {
logcat_panic(false, "failed to set the log size");
if (setLogSize) {
if (android_logger_set_log_size(dev->logger, setLogSize)) {
setSizeFail = setSizeFail ?: dev->device;
}
}
if (getLogSize) {
long size, readable;
long size = android_logger_get_log_size(dev->logger);
long readable = android_logger_get_log_readable_size(dev->logger);
size = android_logger_get_log_size(dev->logger);
if (size < 0) {
logcat_panic(false, "failed to get the log size");
if ((size < 0) || (readable < 0)) {
getSizeFail = getSizeFail ?: dev->device;
} else {
printf("%s: ring buffer is %ld%sb (%ld%sb consumed), "
"max entry is %db, max payload is %db\n", dev->device,
value_of_size(size), multiplier_of_size(size),
value_of_size(readable), multiplier_of_size(readable),
(int) LOGGER_ENTRY_MAX_LEN,
(int) LOGGER_ENTRY_MAX_PAYLOAD);
}
readable = android_logger_get_log_readable_size(dev->logger);
if (readable < 0) {
logcat_panic(false, "failed to get the readable log size");
}
printf("%s: ring buffer is %ld%sb (%ld%sb consumed), "
"max entry is %db, max payload is %db\n", dev->device,
value_of_size(size), multiplier_of_size(size),
value_of_size(readable), multiplier_of_size(readable),
(int) LOGGER_ENTRY_MAX_LEN, (int) LOGGER_ENTRY_MAX_PAYLOAD);
}
dev = dev->next;
}
// report any errors in the above loop and exit
if (openDeviceFail) {
logcat_panic(false, "Unable to open log device '%s'\n", openDeviceFail);
}
if (clearFail) {
logcat_panic(false, "failed to clear the '%s' log\n", clearFail);
}
if (setSizeFail) {
logcat_panic(false, "failed to set the '%s' log size\n", setSizeFail);
}
if (getSizeFail) {
logcat_panic(false, "failed to get the readable '%s' log size",
getSizeFail);
}
if (setPruneList) {
size_t len = strlen(setPruneList);

View file

@ -96,8 +96,7 @@ int CommandListener::ClearCmd::runCommand(SocketClient *cli,
return 0;
}
mBuf.clear((log_id_t) id, uid);
cli->sendMsg("success");
cli->sendMsg(mBuf.clear((log_id_t) id, uid) ? "busy" : "success");
return 0;
}

View file

@ -374,8 +374,10 @@ public:
//
// mLogElementsLock must be held when this function is called.
//
void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
LogTimeEntry *oldest = NULL;
bool busy = false;
bool clearAll = pruneRows == ULONG_MAX;
LogTimeEntry::lock();
@ -393,35 +395,31 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
LogBufferElementCollection::iterator it;
if (caller_uid != AID_ROOT) {
// Only here if clearAll condition (pruneRows == ULONG_MAX)
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
if (oldest && (oldest->mStart <= e->getSequence())) {
break;
}
if (e->getLogId() != id) {
if ((e->getLogId() != id) || (e->getUid() != caller_uid)) {
++it;
continue;
}
if (e->getUid() == caller_uid) {
it = erase(it);
pruneRows--;
if (pruneRows == 0) {
break;
}
} else {
++it;
if (oldest && (oldest->mStart <= e->getSequence())) {
oldest->triggerSkip_Locked(id, pruneRows);
busy = true;
break;
}
it = erase(it);
pruneRows--;
}
LogTimeEntry::unlock();
return;
return busy;
}
// prune by worst offender by uid
bool hasBlacklist = mPrune.naughty();
while (pruneRows > 0) {
while (!clearAll && (pruneRows > 0)) {
// recalculate the worst offender on every batched pass
uid_t worst = (uid_t) -1;
size_t worst_sizes = 0;
@ -478,6 +476,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
LogBufferElement *e = *it;
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
break;
}
@ -585,7 +584,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
bool whitelist = false;
bool hasWhitelist = mPrune.nice();
bool hasWhitelist = mPrune.nice() && !clearAll;
it = mLogElements.begin();
while((pruneRows > 0) && (it != mLogElements.end())) {
LogBufferElement *e = *it;
@ -596,6 +595,8 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
if (whitelist) {
break;
}
@ -631,6 +632,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
@ -646,13 +648,50 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
LogTimeEntry::unlock();
return (pruneRows > 0) && busy;
}
// clear all rows of type "id" from the buffer.
void LogBuffer::clear(log_id_t id, uid_t uid) {
pthread_mutex_lock(&mLogElementsLock);
prune(id, ULONG_MAX, uid);
pthread_mutex_unlock(&mLogElementsLock);
bool LogBuffer::clear(log_id_t id, uid_t uid) {
bool busy = true;
// If it takes more than 4 tries (seconds) to clear, then kill reader(s)
for (int retry = 4;;) {
if (retry == 1) { // last pass
// Check if it is still busy after the sleep, we say prune
// one entry, not another clear run, so we are looking for
// the quick side effect of the return value to tell us if
// we have a _blocked_ reader.
pthread_mutex_lock(&mLogElementsLock);
busy = prune(id, 1, uid);
pthread_mutex_unlock(&mLogElementsLock);
// It is still busy, blocked reader(s), lets kill them all!
// otherwise, lets be a good citizen and preserve the slow
// readers and let the clear run (below) deal with determining
// if we are still blocked and return an error code to caller.
if (busy) {
LogTimeEntry::lock();
LastLogTimes::iterator times = mTimes.begin();
while (times != mTimes.end()) {
LogTimeEntry *entry = (*times);
// Killer punch
if (entry->owned_Locked() && entry->isWatching(id)) {
entry->release_Locked();
}
times++;
}
LogTimeEntry::unlock();
}
}
pthread_mutex_lock(&mLogElementsLock);
busy = prune(id, ULONG_MAX, uid);
pthread_mutex_unlock(&mLogElementsLock);
if (!busy || !--retry) {
break;
}
sleep (1); // Let reader(s) catch up after notification
}
return busy;
}
// get the used space associated with "id".

View file

@ -63,7 +63,7 @@ public:
int (*filter)(const LogBufferElement *element, void *arg) = NULL,
void *arg = NULL);
void clear(log_id_t id, uid_t uid = AID_ROOT);
bool clear(log_id_t id, uid_t uid = AID_ROOT);
unsigned long getSize(log_id_t id);
int setSize(log_id_t id, unsigned long size);
unsigned long getSizeUsed(log_id_t id);
@ -86,7 +86,7 @@ public:
private:
void maybePrune(log_id_t id);
void prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);
bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);
LogBufferElementCollection::iterator erase(
LogBufferElementCollection::iterator it, bool engageStats = true);
};

View file

@ -42,7 +42,6 @@ LogCommand::LogCommand(const char *cmd) : FrameworkCommand(cmd) {
static bool groupIsLog(char *buf) {
char *ptr;
static const char ws[] = " \n";
bool ret = false;
for (buf = strtok_r(buf, ws, &ptr); buf; buf = strtok_r(NULL, ws, &ptr)) {
errno = 0;
@ -51,10 +50,10 @@ static bool groupIsLog(char *buf) {
return false;
}
if (Gid == AID_LOG) {
ret = true;
return true;
}
}
return ret;
return false;
}
bool clientHasLogCredentials(SocketClient * cli) {
@ -69,61 +68,79 @@ bool clientHasLogCredentials(SocketClient * cli) {
}
// FYI We will typically be here for 'adb logcat'
bool ret = false;
char filename[1024];
snprintf(filename, sizeof(filename), "/proc/%d/status", cli->getPid());
FILE *file = fopen(filename, "r");
if (!file) {
return ret;
}
char filename[256];
snprintf(filename, sizeof(filename), "/proc/%u/status", cli->getPid());
bool ret;
bool foundLog = false;
bool foundGid = false;
bool foundUid = false;
char line[1024];
while (fgets(line, sizeof(line), file)) {
static const char groups_string[] = "Groups:\t";
static const char uid_string[] = "Uid:\t";
static const char gid_string[] = "Gid:\t";
if (strncmp(groups_string, line, strlen(groups_string)) == 0) {
ret = groupIsLog(line + strlen(groups_string));
if (!ret) {
break;
}
} else if (strncmp(uid_string, line, strlen(uid_string)) == 0) {
uid_t u[4] = { (uid_t) -1, (uid_t) -1, (uid_t) -1, (uid_t) -1};
sscanf(line + strlen(uid_string), "%u\t%u\t%u\t%u",
&u[0], &u[1], &u[2], &u[3]);
// Protect against PID reuse by checking that the UID is the same
if ((uid != u[0]) || (uid != u[1]) || (uid != u[2]) || (uid != u[3])) {
ret = false;
break;
}
foundUid = true;
} else if (strncmp(gid_string, line, strlen(gid_string)) == 0) {
gid_t g[4] = { (gid_t) -1, (gid_t) -1, (gid_t) -1, (gid_t) -1};
sscanf(line + strlen(gid_string), "%u\t%u\t%u\t%u",
&g[0], &g[1], &g[2], &g[3]);
// Protect against PID reuse by checking that the GID is the same
if ((gid != g[0]) || (gid != g[1]) || (gid != g[2]) || (gid != g[3])) {
ret = false;
break;
}
foundGid = true;
//
// Reading /proc/<pid>/status is rife with race conditions. All of /proc
// suffers from this and its use should be minimized. However, we have no
// choice.
//
// Notably the content from one 4KB page to the next 4KB page can be from a
// change in shape even if we are gracious enough to attempt to read
// atomically. getline can not even guarantee a page read is not split up
// and in effect can read from different vintages of the content.
//
// We are finding out in the field that a 'logcat -c' via adb occasionally
// is returned with permission denied when we did only one pass and thus
// breaking scripts. For security we still err on denying access if in
// doubt, but we expect the falses should be reduced significantly as
// three times is a charm.
//
for (int retry = 3;
!(ret = foundGid && foundUid && foundLog) && retry;
--retry) {
FILE *file = fopen(filename, "r");
if (!file) {
continue;
}
}
fclose(file);
char *line = NULL;
size_t len = 0;
while (getline(&line, &len, file) > 0) {
static const char groups_string[] = "Groups:\t";
static const char uid_string[] = "Uid:\t";
static const char gid_string[] = "Gid:\t";
if (!foundGid || !foundUid) {
ret = false;
if (strncmp(groups_string, line, sizeof(groups_string) - 1) == 0) {
if (groupIsLog(line + sizeof(groups_string) - 1)) {
foundLog = true;
}
} else if (strncmp(uid_string, line, sizeof(uid_string) - 1) == 0) {
uid_t u[4] = { (uid_t) -1, (uid_t) -1, (uid_t) -1, (uid_t) -1};
sscanf(line + sizeof(uid_string) - 1, "%u\t%u\t%u\t%u",
&u[0], &u[1], &u[2], &u[3]);
// Protect against PID reuse by checking that UID is the same
if ((uid == u[0])
&& (uid == u[1])
&& (uid == u[2])
&& (uid == u[3])) {
foundUid = true;
}
} else if (strncmp(gid_string, line, sizeof(gid_string) - 1) == 0) {
gid_t g[4] = { (gid_t) -1, (gid_t) -1, (gid_t) -1, (gid_t) -1};
sscanf(line + sizeof(gid_string) - 1, "%u\t%u\t%u\t%u",
&g[0], &g[1], &g[2], &g[3]);
// Protect against PID reuse by checking that GID is the same
if ((gid == g[0])
&& (gid == g[1])
&& (gid == g[2])
&& (gid == g[3])) {
foundGid = true;
}
}
}
free(line);
fclose(file);
}
return ret;

View file

@ -128,9 +128,9 @@ void *LogTimeEntry::threadStart(void *obj) {
lock();
while (me->threadRunning && !me->isError_Locked()) {
uint64_t start = me->mStart;
uint64_t start = me->mStart;
while (me->threadRunning && !me->isError_Locked()) {
unlock();
if (me->mTail) {
@ -143,8 +143,11 @@ void *LogTimeEntry::threadStart(void *obj) {
if (start == LogBufferElement::FLUSH_ERROR) {
me->error_Locked();
break;
}
me->mStart = start + 1;
if (me->mNonBlock || !me->threadRunning || me->isError_Locked()) {
break;
}