Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 206ed8e2 authored by Mark Salyzyn's avatar Mark Salyzyn
Browse files

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
parent 24bccbcf

logd/LogBuffer.cpp

+19 −9
Original line number Diff line number Diff line
@@ -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,