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

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",
+            openDeviceFail = openDeviceFail ?: dev->device;
-                         dev->device);
+            dev = dev->next;
+            continue;
         }
 
         if (clearLog) {
-            int ret;
+            if (android_logger_clear(dev->logger)) {
-            ret = android_logger_clear(dev->logger);
+                clearFail = clearFail ?: dev->device;
-            if (ret) {
-                logcat_panic(false, "failed to clear the log");
             }
         }
 
-        if (setLogSize && android_logger_set_log_size(dev->logger, setLogSize)) {
+        if (setLogSize) {
-            logcat_panic(false, "failed to set the log size");
+            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) || (readable < 0)) {
-            if (size < 0) {
+                getSizeFail = getSizeFail ?: dev->device;
-                logcat_panic(false, "failed to get the log size");
+            } 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);

logd/CommandListener.cpp

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

logd/LogBuffer.cpp

@@ -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())) {
+            if ((e->getLogId() != id) || (e->getUid() != caller_uid)) {
-                break;
-            }
-
-            if (e->getLogId() != id) {
                 ++it;
                 continue;
             }
 
-            if (e->getUid() == caller_uid) {
+            if (oldest && (oldest->mStart <= e->getSequence())) {
-                it = erase(it);
+                oldest->triggerSkip_Locked(id, pruneRows);
-                pruneRows--;
+                busy = true;
-                if (pruneRows == 0) {
+                break;
-                    break;
-                }
-            } else {
-                ++it;
             }
+
+            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) {
+bool LogBuffer::clear(log_id_t id, uid_t uid) {
-    pthread_mutex_lock(&mLogElementsLock);
+    bool busy = true;
-    prune(id, ULONG_MAX, uid);
+    // If it takes more than 4 tries (seconds) to clear, then kill reader(s)
-    pthread_mutex_unlock(&mLogElementsLock);
+    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".

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);
 };

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

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;
         }