logd: don't send logs before the start time on the first flushTo()

Logs in logd's buffer are not in time order.

If a client connects and requests logs from a given timestamp, we
start at the beginning of the buffer and find the first entry that has
happened since that timestamp and use its sequence number to flush
logs from.  This ensures that we get all logs accumulated in the
buffer since that time stamp and not just the most recent.

However there may be other logs in the buffer that happened before the
timestamp and have likely been already served to the client, therefore
we do not flush those.

We only do this for the first flush, since once we have flushed all of
the logs in the buffer, if another log comes in with a timestamp
earlier than the requested timestamp, it must be out of order and not
seen yet, since it is new even to logd.

Note! This is still broken.  There is a race that logs before the
timestamp may come in out of order since the last time the client
disconnected and before it reconnects.  The *only* solution to this
problem is that clients need to request logs after a given sequence
number.  That will be done as a separate liblog API change, while
these changes put in the ground work to make that possible.

Note 2: the security log implementation, which is one of the most
important users of this, already captures logs from seconds before the
last previous log to work around issues with timestamps.  That
workaround mitigates the above issue.

Test: logs work with logcat -t
Change-Id: If1a62a90c082d98c4cf2eb5c92ae3b7e89850cf2

logd/LogReader.cpp

@@ -136,13 +136,13 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
             const pid_t mPid;
             const unsigned mLogMask;
             bool startTimeSet;
-            log_time& start;
+            const log_time start;
             uint64_t& sequence;
             uint64_t last;
             bool isMonotonic;
 
           public:
-            LogFindStart(unsigned logMask, pid_t pid, log_time& start, uint64_t& sequence,
+            LogFindStart(unsigned logMask, pid_t pid, log_time start, uint64_t& sequence,
                          bool isMonotonic)
                 : mPid(pid),
                   mLogMask(logMask),
@@ -202,8 +202,8 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
     }
 
     LogTimeEntry::wrlock();
-    auto entry = std::make_unique<LogTimeEntry>(
-        *this, cli, nonBlock, tail, logMask, pid, sequence, timeout);
+    auto entry = std::make_unique<LogTimeEntry>(*this, cli, nonBlock, tail, logMask, pid, start,
+                                                sequence, timeout);
     if (!entry->startReader_Locked()) {
         LogTimeEntry::unlock();
         return false;

logd/LogTimes.cpp

@@ -26,8 +26,8 @@
 pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
 
 LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
-                           unsigned long tail, log_mask_t logMask, pid_t pid, uint64_t start,
-                           uint64_t timeout)
+                           unsigned long tail, log_mask_t logMask, pid_t pid, log_time start_time,
+                           uint64_t start, uint64_t timeout)
     : leadingDropped(false),
       mReader(reader),
       mLogMask(logMask),
@@ -36,6 +36,7 @@ LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBloc
       mTail(tail),
       mIndex(0),
       mClient(client),
+      mStartTime(start_time),
       mStart(start),
       mNonBlock(nonBlock) {
     mTimeout.tv_sec = timeout / NS_PER_SEC;
@@ -102,6 +103,15 @@ void* LogTimeEntry::threadStart(void* obj) {
         start = logbuf.flushTo(client, start, me->mLastTid, privileged,
                                security, FilterSecondPass, me);
 
+        // We only ignore entries before the original start time for the first flushTo(), if we
+        // get entries after this first flush before the original start time, then the client
+        // wouldn't have seen them.
+        // Note: this is still racy and may skip out of order events that came in since the last
+        // time the client disconnected and then reconnected with the new start time.  The long term
+        // solution here is that clients must request events since a specific sequence number.
+        me->mStartTime.tv_sec = 0;
+        me->mStartTime.tv_nsec = 0;
+
         wrlock();
 
         if (start == LogBufferElement::FLUSH_ERROR) {
@@ -158,8 +168,8 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement* element, void* obj) {
         me->mStart = element->getSequence();
     }
 
-    if ((!me->mPid || (me->mPid == element->getPid())) &&
-        (me->isWatching(element->getLogId()))) {
+    if ((!me->mPid || me->mPid == element->getPid()) && me->isWatching(element->getLogId()) &&
+        (me->mStartTime == log_time::EPOCH || me->mStartTime <= element->getRealTime())) {
         ++me->mCount;
     }
 
@@ -201,6 +211,10 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) {
         goto skip;
     }
 
+    if (me->mStartTime != log_time::EPOCH && element->getRealTime() <= me->mStartTime) {
+        goto skip;
+    }
+
     if (me->mRelease) {
         goto stop;
     }

logd/LogTimes.h

@@ -51,9 +51,11 @@ class LogTimeEntry {
 
   public:
     LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, unsigned long tail,
-                 log_mask_t logMask, pid_t pid, uint64_t start, uint64_t timeout);
+                 log_mask_t logMask, pid_t pid, log_time start_time, uint64_t sequence,
+                 uint64_t timeout);
 
     SocketClient* mClient;
+    log_time mStartTime;
     uint64_t mStart;
     struct timespec mTimeout;  // CLOCK_MONOTONIC based timeout used for log wrapping.
     const bool mNonBlock;