From 206ed8e2d64d41435251e1371834600615439643 Mon Sep 17 00:00:00 2001
From: Mark Salyzyn <salyzyn@google.com>
Date: Thu, 18 May 2017 10:06:00 -0700
Subject: [PATCH] logd: remove start filtration from flushTo (part deux)

We have already searched for the start point, the start filter check
is paranoia that removes out-of-order entries that we are undoubtably
interested in.  Out-of-order entries occur under reader pressure, as
the writer gets pushed back from in-place sorted order and lands it
at the end for the reader to pick it up.  If this occurred during a
batch run or a logger thread wakeup, the entry could be filtered out
and never output to the reader.

We have to treat exact finds for start in the list as terminal when
we search as they represent restarts, depending on the fact that it
is impossible to have the exact same time reported in two log entries
or requested from a batched reader.  This does break down if a log
entry has xxxxxx000 nanoseconds reported, we fix that by making sure
we never log such a case and slip it by a ns.

Found one case where logcat.tail_time* tests failed which was fixed
with this adjustment.

Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 38046067
Bug: 37791296
Bug: 38341453
Change-Id: I4dd2e2596dd67b8d602160dd79661e01805227a9
---
 logd/LogBuffer.cpp | 28 +++++++++++++++++++---------
 1 file changed, 19 insertions(+), 9 deletions(-)

diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index ded6c8cc7..76a4affdc 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -79,10 +79,16 @@ void LogBuffer::init() {
             if (monotonic) {
                 if (!android::isMonotonic(e->mRealTime)) {
                     LogKlog::convertRealToMonotonic(e->mRealTime);
+                    if ((e->mRealTime.tv_nsec % 1000) == 0) {
+                        e->mRealTime.tv_nsec++;
+                    }
                 }
             } else {
                 if (android::isMonotonic(e->mRealTime)) {
                     LogKlog::convertMonotonicToReal(e->mRealTime);
+                    if ((e->mRealTime.tv_nsec % 1000) == 0) {
+                        e->mRealTime.tv_nsec++;
+                    }
                 }
             }
             ++it;
@@ -194,6 +200,11 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
         return -EINVAL;
     }
 
+    // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns.
+    // This prevents any chance that an outside source can request an
+    // exact entry with time specified in ms or us precision.
+    if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec;
+
     LogBufferElement* elem =
         new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len);
     if (log_id != LOG_ID_SECURITY) {
@@ -1109,6 +1120,9 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
             LogBufferElement* element = *it;
             if (element->getRealTime() > start) {
                 last = it;
+            } else if (element->getRealTime() == start) {
+                last = ++it;
+                break;
             } else if (!--count || (element->getRealTime() < min)) {
                 break;
             }
@@ -1116,7 +1130,7 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
         it = last;
     }
 
-    log_time max = start;
+    log_time curr = start;
 
     LogBufferElement* lastElement = nullptr;  // iterator corruption paranoia
     static const size_t maxSkip = 4194304;    // maximum entries to skip
@@ -1142,10 +1156,6 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
             continue;
         }
 
-        if (element->getRealTime() <= start) {
-            continue;
-        }
-
         // NB: calling out to another object with wrlock() held (safe)
         if (filter) {
             int ret = (*filter)(element, arg);
@@ -1172,10 +1182,10 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
         unlock();
 
         // range locking in LastLogTimes looks after us
-        max = element->flushTo(reader, this, privileged, sameTid);
+        curr = element->flushTo(reader, this, privileged, sameTid);
 
-        if (max == element->FLUSH_ERROR) {
-            return max;
+        if (curr == element->FLUSH_ERROR) {
+            return curr;
         }
 
         skip = maxSkip;
@@ -1183,7 +1193,7 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
     }
     unlock();
 
-    return max;
+    return curr;
 }
 
 std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid,