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
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index ded6c8c..76a4aff 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -79,10 +79,16 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
}
unlock();
- return max;
+ return curr;
}
std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid,