logd: wakeup on wrap or timeout

If a timeout is specified for the reader, then go to sleep
with the socket open. If the start time is about to get
pruned in the specified log buffers, then wakeup and dump
the logs; or wakeup on timeout, whichever comes first.

Bug: 25929746
Change-Id: I7d2421c2c5083b33747b84f74d9a560d3ba645df

6 files changed, 106 insertions, 40 deletions

diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp
index 823a842fb..bf650cdaa 100644
--- a/logd/FlushCommand.cpp
+++ b/logd/FlushCommand.cpp
@@ -27,13 +27,15 @@ FlushCommand::FlushCommand(LogReader &reader,
                            unsigned long tail,
                            unsigned int logMask,
                            pid_t pid,
-                           uint64_t start) :
+                           uint64_t start,
+                           uint64_t timeout) :
         mReader(reader),
         mNonBlock(nonBlock),
         mTail(tail),
         mLogMask(logMask),
         mPid(pid),
-        mStart(start) {
+        mStart(start),
+        mTimeout(timeout) {
 }
 
 // runSocketCommand is called once for every open client on the
@@ -54,6 +56,10 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
     while(it != times.end()) {
         entry = (*it);
         if (entry->mClient == client) {
+            if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) {
+                LogTimeEntry::unlock();
+                return;
+            }
             entry->triggerReader_Locked();
             if (entry->runningReader_Locked()) {
                 LogTimeEntry::unlock();
@@ -71,7 +77,8 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
             LogTimeEntry::unlock();
             return;
         }
-        entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, mPid, mStart);
+        entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask,
+                                 mPid, mStart, mTimeout);
         times.push_front(entry);
     }
 
diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h
index 61c6858c2..e0f2212be 100644
--- a/logd/FlushCommand.h
+++ b/logd/FlushCommand.h
@@ -32,6 +32,7 @@ class FlushCommand : public SocketClientCommand {
     unsigned int mLogMask;
     pid_t mPid;
     uint64_t mStart;
+    uint64_t mTimeout;
 
 public:
     FlushCommand(LogReader &mReader,
@@ -39,7 +40,8 @@ public:
                  unsigned long tail = -1,
                  unsigned int logMask = -1,
                  pid_t pid = 0,
-                 uint64_t start = 1);
+                 uint64_t start = 1,
+                 uint64_t timeout = 0);
     virtual void runSocketCommand(SocketClient *client);
 
     static bool hasReadLogs(SocketClient *client);
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index c8127c3ac..6770bb7f2 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -129,41 +129,57 @@ void LogBuffer::init() {
     }
     bool lastMonotonic = monotonic;
     monotonic = android_log_clockid() == CLOCK_MONOTONIC;
-    if (lastMonotonic == monotonic) {
-        return;
+    if (lastMonotonic != monotonic) {
+        //
+        // Fixup all timestamps, may not be 100% accurate, but better than
+        // throwing what we have away when we get 'surprised' by a change.
+        // In-place element fixup so no need to check reader-lock. Entries
+        // should already be in timestamp order, but we could end up with a
+        // few out-of-order entries if new monotonics come in before we
+        // are notified of the reinit change in status. A Typical example would
+        // be:
+        //  --------- beginning of system
+        //      10.494082   184   201 D Cryptfs : Just triggered post_fs_data
+        //  --------- beginning of kernel
+        //       0.000000     0     0 I         : Initializing cgroup subsys
+        // as the act of mounting /data would trigger persist.logd.timestamp to
+        // be corrected. 1/30 corner case YMMV.
+        //
+        pthread_mutex_lock(&mLogElementsLock);
+        LogBufferElementCollection::iterator it = mLogElements.begin();
+        while((it != mLogElements.end())) {
+            LogBufferElement *e = *it;
+            if (monotonic) {
+                if (!android::isMonotonic(e->mRealTime)) {
+                    LogKlog::convertRealToMonotonic(e->mRealTime);
+                }
+            } else {
+                if (android::isMonotonic(e->mRealTime)) {
+                    LogKlog::convertMonotonicToReal(e->mRealTime);
+                }
+            }
+            ++it;
+        }
+        pthread_mutex_unlock(&mLogElementsLock);
     }
 
+    // We may have been triggered by a SIGHUP. Release any sleeping reader
+    // threads to dump their current content.
     //
-    // Fixup all timestamps, may not be 100% accurate, but better than
-    // throwing what we have away when we get 'surprised' by a change.
-    // In-place element fixup so no need to check reader-lock. Entries
-    // should already be in timestamp order, but we could end up with a
-    // few out-of-order entries if new monotonics come in before we
-    // are notified of the reinit change in status. A Typical example would
-    // be:
-    //  --------- beginning of system
-    //      10.494082   184   201 D Cryptfs : Just triggered post_fs_data
-    //  --------- beginning of kernel
-    //       0.000000     0     0 I         : Initializing cgroup subsys cpuacct
-    // as the act of mounting /data would trigger persist.logd.timestamp to
-    // be corrected. 1/30 corner case YMMV.
-    //
-    pthread_mutex_lock(&mLogElementsLock);
-    LogBufferElementCollection::iterator it = mLogElements.begin();
-    while((it != mLogElements.end())) {
-        LogBufferElement *e = *it;
-        if (monotonic) {
-            if (!android::isMonotonic(e->mRealTime)) {
-                LogKlog::convertRealToMonotonic(e->mRealTime);
-            }
-        } else {
-            if (android::isMonotonic(e->mRealTime)) {
-                LogKlog::convertMonotonicToReal(e->mRealTime);
-            }
+    // NB: this is _not_ performed in the context of a SIGHUP, it is
+    // performed during startup, and in context of reinit administrative thread
+    LogTimeEntry::lock();
+
+    LastLogTimes::iterator times = mTimes.begin();
+    while(times != mTimes.end()) {
+        LogTimeEntry *entry = (*times);
+        if (entry->owned_Locked()) {
+            entry->triggerReader_Locked();
         }
-        ++it;
+        times++;
     }
-    pthread_mutex_unlock(&mLogElementsLock);
+
+    LogTimeEntry::unlock();
 }
 
 LogBuffer::LogBuffer(LastLogTimes *times):
@@ -429,7 +445,10 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
     while(t != mTimes.end()) {
         LogTimeEntry *entry = (*t);
         if (entry->owned_Locked() && entry->isWatching(id)
-                && (!oldest || (oldest->mStart > entry->mStart))) {
+                && (!oldest ||
+                    (oldest->mStart > entry->mStart) ||
+                    ((oldest->mStart == entry->mStart) &&
+                     (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
             oldest = entry;
         }
         t++;
@@ -448,8 +467,12 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
             }
 
             if (oldest && (oldest->mStart <= e->getSequence())) {
-                oldest->triggerSkip_Locked(id, pruneRows);
                 busy = true;
+                if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
+                    oldest->triggerReader_Locked();
+                } else {
+                    oldest->triggerSkip_Locked(id, pruneRows);
+                }
                 break;
             }
 
@@ -523,6 +546,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
 
             if (oldest && (oldest->mStart <= e->getSequence())) {
                 busy = true;
+                if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
+                    oldest->triggerReader_Locked();
+                }
                 break;
             }
 
@@ -648,6 +674,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
             if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                 // kick a misbehaving log reader client off the island
                 oldest->release_Locked();
+            } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
+                oldest->triggerReader_Locked();
             } else {
                 oldest->triggerSkip_Locked(id, pruneRows);
             }
@@ -680,6 +708,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                     // kick a misbehaving log reader client off the island
                     oldest->release_Locked();
+                } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
+                    oldest->triggerReader_Locked();
                 } else {
                     oldest->triggerSkip_Locked(id, pruneRows);
                 }
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 06135ddc0..c2d65b601 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -67,6 +67,14 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
         start.strptime(cp + sizeof(_start) - 1, "%s.%q");
     }
 
+    uint64_t timeout = 0;
+    static const char _timeout[] = " timeout=";
+    cp = strstr(buffer, _timeout);
+    if (cp) {
+        timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC +
+                  log_time(CLOCK_REALTIME).nsec();
+    }
+
     unsigned int logMask = -1;
     static const char _logIds[] = " lids=";
     cp = strstr(buffer, _logIds);
@@ -166,7 +174,7 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
         }
     }
 
-    FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence);
+    FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence, timeout);
     command.runSocketCommand(cli);
     return true;
 }
diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
index 229be3cd5..b4c97a985 100644
--- a/logd/LogTimes.cpp
+++ b/logd/LogTimes.cpp
@@ -14,6 +14,7 @@
  * limitations under the License.
  */
 
+#include <errno.h>
 #include <sys/prctl.h>
 
 #include "FlushCommand.h"
@@ -26,7 +27,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
 LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
                            bool nonBlock, unsigned long tail,
                            unsigned int logMask, pid_t pid,
-                           uint64_t start) :
+                           uint64_t start, uint64_t timeout) :
         mRefCount(1),
         mRelease(false),
         mError(false),
@@ -42,6 +43,8 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
         mStart(start),
         mNonBlock(nonBlock),
         mEnd(LogBufferElement::getCurrentSequence()) {
+    mTimeout.tv_sec = timeout / NS_PER_SEC;
+    mTimeout.tv_nsec = timeout % NS_PER_SEC;
     pthread_cond_init(&threadTriggeredCondition, NULL);
     cleanSkip_Locked();
 }
@@ -131,6 +134,19 @@ void *LogTimeEntry::threadStart(void *obj) {
     uint64_t start = me->mStart;
 
     while (me->threadRunning && !me->isError_Locked()) {
+
+        if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
+            if (pthread_cond_timedwait(&me->threadTriggeredCondition,
+                                       &timesLock,
+                                       &me->mTimeout) == ETIMEDOUT) {
+                me->mTimeout.tv_sec = 0;
+                me->mTimeout.tv_nsec = 0;
+            }
+            if (!me->threadRunning || me->isError_Locked()) {
+                break;
+            }
+        }
+
         unlock();
 
         if (me->mTail) {
@@ -154,7 +170,9 @@ void *LogTimeEntry::threadStart(void *obj) {
 
         me->cleanSkip_Locked();
 
-        pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
+        if (!me->mTimeout.tv_sec && !me->mTimeout.tv_nsec) {
+            pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
+        }
     }
 
     unlock();
diff --git a/logd/LogTimes.h b/logd/LogTimes.h
index 39bcdd4e6..1117088e5 100644
--- a/logd/LogTimes.h
+++ b/logd/LogTimes.h
@@ -50,10 +50,11 @@ class LogTimeEntry {
 public:
     LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock,
                  unsigned long tail, unsigned int logMask, pid_t pid,
-                 uint64_t start);
+                 uint64_t start, uint64_t timeout);
 
     SocketClient *mClient;
     uint64_t mStart;
+    struct timespec mTimeout;
     const bool mNonBlock;
     const uint64_t mEnd; // only relevant if mNonBlock