From 86eb38f3caaddbd54c0339e6b2abeab254ae98fb Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 1 Sep 2015 08:40:39 -0700 Subject: [PATCH 1/5] logd: clientHasLogCredentials false negatives Vote three times in /proc/pid/status to look for AID_LOG group If not, we may default to the callers UID, and the net result is to perform the task related to that UID. For adb logcat and shell logcat, the UID is AID_SHELL which typically has no logs, leaving no net action taken. Bug: 23711431 Change-Id: I2b5900a2d37173bd995eb308ee9ecafa20602b62 --- logd/LogCommand.cpp | 119 +++++++++++++++++++++++++------------------- 1 file changed, 68 insertions(+), 51 deletions(-) diff --git a/logd/LogCommand.cpp b/logd/LogCommand.cpp index 06d865cd5..6d0e92e4e 100644 --- a/logd/LogCommand.cpp +++ b/logd/LogCommand.cpp @@ -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//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; From 603b8e50c8e542b4c0e51ed742a714cb14e8dd9b Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 16 Sep 2015 15:34:00 -0700 Subject: [PATCH 2/5] logcat: do not exit buffer loop on error - Alter logcat to collect error(s) for open, clear, get size or set size; moving on to other buffer ids. Then after loop completed, report and exit for the last error reported. Bug: 23711431 Change-Id: I63a729d27544ea8d5c6119625c1de0210be0eb70 --- logcat/logcat.cpp | 63 ++++++++++++++++++++++++++++++----------------- 1 file changed, 40 insertions(+), 23 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 54cbc20ee..ddbfb3e5d 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -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); From de4bb9c1a704d0eab3320b43c3964342f4b662df Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 16 Sep 2015 15:34:00 -0700 Subject: [PATCH 3/5] logd: update region lock after entry has passed to reader socket - The reader region level indicates the location to protect, but once it has been passed to the calling reader, then allow us to go one beyond so that a clear or prune thread can remove the entry. Bug: 23711431 Change-Id: I0f2389858dd8c83366c034360f67d7c363625b56 --- logd/LogTimes.cpp | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index 68a068008..229be3cd5 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -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; } From c5dc970edc202f89ecdd0c2fe988c7e2b8408bef Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 16 Sep 2015 15:34:00 -0700 Subject: [PATCH 4/5] logd: clear return and deal with busy if readers locked - Propagate to caller the clearing errors, busy blocked by reader. - For clear, perform retries within logd with a one second lul each, telling readers to skip, but on final retry to kill all readers if problem still persists due to block reader (or high volume logspammer). Bug: 23711431 Change-Id: Ie4c46bc9480a7f49b96a81fae25a95c603270c33 --- logd/CommandListener.cpp | 3 +-- logd/LogBuffer.cpp | 56 +++++++++++++++++++++++++++++++++++----- logd/LogBuffer.h | 4 +-- 3 files changed, 53 insertions(+), 10 deletions(-) diff --git a/logd/CommandListener.cpp b/logd/CommandListener.cpp index 031c74018..eafa28fb4 100644 --- a/logd/CommandListener.cpp +++ b/logd/CommandListener.cpp @@ -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; } diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index c2f846ef2..35ee6f365 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -374,8 +374,9 @@ 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; LogTimeEntry::lock(); @@ -397,6 +398,8 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { LogBufferElement *e = *it; if (oldest && (oldest->mStart <= e->getSequence())) { + oldest->triggerSkip_Locked(id, pruneRows); + busy = true; break; } @@ -416,7 +419,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } } LogTimeEntry::unlock(); - return; + return busy; } // prune by worst offender by uid @@ -478,6 +481,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; } @@ -596,6 +600,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 +637,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 +653,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". diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index de7669310..d8e0b90f2 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -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); }; From 2b25c66070f73413013caa48e1c171cb895869b5 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 16 Sep 2015 15:34:00 -0700 Subject: [PATCH 5/5] logd: clearAll by UID speedup - If doing a clear, skip accounting - Ensure for busy checking, behind a region lock for instance, only break out if there was something to do. Basically move the filter actions first, and defer checking the region lock to the ends of the loops. Bug: 23711431 Change-Id: Icc984f406880633516fb17dda84188a30d092e01 --- logd/LogBuffer.cpp | 27 +++++++++++---------------- 1 file changed, 11 insertions(+), 16 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 35ee6f365..5cfc02f32 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -377,6 +377,7 @@ public: 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(); @@ -394,29 +395,23 @@ bool 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 ((e->getLogId() != id) || (e->getUid() != caller_uid)) { + ++it; + continue; + } + if (oldest && (oldest->mStart <= e->getSequence())) { oldest->triggerSkip_Locked(id, pruneRows); busy = true; break; } - if (e->getLogId() != id) { - ++it; - continue; - } - - if (e->getUid() == caller_uid) { - it = erase(it); - pruneRows--; - if (pruneRows == 0) { - break; - } - } else { - ++it; - } + it = erase(it); + pruneRows--; } LogTimeEntry::unlock(); return busy; @@ -424,7 +419,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { // 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; @@ -589,7 +584,7 @@ bool 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;