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

Commit da6495d0 authored by TraianX Schiau's avatar TraianX Schiau Committed by Mark Salyzyn
Browse files

logd: Fix pruning 



In a scenario in which an on-line (blocking) client is running and
a clean is attempted (logcat -c), the following can be observed:

1) the on-line logger seems to freeze
2) any other clear attempt will have no effect

What is actually happening:

In this case prune function will "instruct" the oldest timeEntry
to skip a huge number (very close to ULONG_MAX) of messages, this
being the cause of 1.

Since the consumer thread will skip all the log entries, mStart
updating will also be skipped. So a new cleaning attempt will have
the same oldest entry, nothing will be done.

Fix description:
a. keep a separated skipAhead count for individual log buffers (log_id_t)
      LogTimeEntry::LogTimeEntry
      LogTimeEntry::FilterSecondPass
      LogTimeEntry::skipAhead
      LogTimeEntry::riggerSkip_Locked

b. update LogTimeEntry::mStart even if the current message is skipped
      LogTimeEntry::FilterSecondPass

c. while pruning, only take into account the LogTimeEntrys that are monitoring
   the log_id in question, and provide a public method of checking this.
      LogTimeEntry::isWatching
      LogTimeEntry::FilterFirstPass
      LogTimeEntry::FilterSecondPass

d. Reset the skip cont befor the client thtread starts to sleep, at this point
   we should be up to date.
      LogTimeEntry::cleanSkip_Locked
      LogTimeEntry::threadStart

Change-Id: I1b369dc5b02476e633e52578266a644e37e188a5
Signed-off-by: default avatarTraianX Schiau <traianx.schiau@intel.com>
parent da3dec3c

logd/LogBuffer.cpp

+3 −3
Original line number Diff line number Diff line
@@ -242,7 +242,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { 
    LastLogTimes::iterator t = mTimes.begin();

    while(t != mTimes.end()) {

        LogTimeEntry *entry = (*t);

        if (entry->owned_Locked()

        if (entry->owned_Locked() && entry->isWatching(id)

                && (!oldest || (oldest->mStart > entry->mStart))) {

            oldest = entry;

        }
@@ -354,7 +354,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { 
                        // kick a misbehaving log reader client off the island

                        oldest->release_Locked();

                    } else {

                        oldest->triggerSkip_Locked(pruneRows);

                        oldest->triggerSkip_Locked(id, pruneRows);

                    }

                }

                break;
@@ -385,7 +385,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { 
                        // kick a misbehaving log reader client off the island

                        oldest->release_Locked();

                    } else {

                        oldest->triggerSkip_Locked(pruneRows);

                        oldest->triggerSkip_Locked(id, pruneRows);

                    }

                    break;

                }

logd/LogTimes.cpp

+16 −8
Original line number Diff line number Diff line
@@ -36,7 +36,6 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, 
        , mReader(reader)

        , mLogMask(logMask)

        , mPid(pid)

        , skipAhead(0)

        , mCount(0)

        , mTail(tail)

        , mIndex(0)
@@ -46,6 +45,7 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, 
        , mEnd(CLOCK_MONOTONIC)

{

        pthread_cond_init(&threadTriggeredCondition, NULL);

        cleanSkip_Locked();

}



void LogTimeEntry::startReader_Locked(void) {
@@ -148,6 +148,8 @@ void *LogTimeEntry::threadStart(void *obj) { 
            break;

        }



        me->cleanSkip_Locked();



        pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);

    }
@@ -169,7 +171,7 @@ bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { 
    }



    if ((!me->mPid || (me->mPid == element->getPid()))

            && (me->mLogMask & (1 << element->getLogId()))) {

            && (me->isWatching(element->getLogId()))) {

        ++me->mCount;

    }
@@ -184,19 +186,19 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) 


    LogTimeEntry::lock();



    if (me->skipAhead) {

        me->skipAhead--;

    me->mStart = element->getMonotonicTime();



    if (me->skipAhead[element->getLogId()]) {

        me->skipAhead[element->getLogId()]--;

        goto skip;

    }



    me->mStart = element->getMonotonicTime();



    // Truncate to close race between first and second pass

    if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) {

        goto skip;

    }



    if ((me->mLogMask & (1 << element->getLogId())) == 0) {

    if (!me->isWatching(element->getLogId())) {

        goto skip;

    }
@@ -223,7 +225,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) 
    }



ok:

    if (!me->skipAhead) {

    if (!me->skipAhead[element->getLogId()]) {

        LogTimeEntry::unlock();

        return true;

    }
@@ -233,3 +235,9 @@ skip: 
    LogTimeEntry::unlock();

    return false;

}



void LogTimeEntry::cleanSkip_Locked(void) {

    for (log_id_t i = LOG_ID_MIN; i < LOG_ID_MAX; i = (log_id_t) (i + 1)) {

        skipAhead[i] = 0;

    }

}

logd/LogTimes.h

+5 −3
Original line number Diff line number Diff line
@@ -22,6 +22,7 @@ 
#include <sys/types.h>

#include <sysutils/SocketClient.h>

#include <utils/List.h>

#include <log/log.h>



class LogReader;
@@ -38,7 +39,7 @@ class LogTimeEntry { 
    static void threadStop(void *me);

    const unsigned int mLogMask;

    const pid_t mPid;

    unsigned int skipAhead;

    unsigned int skipAhead[LOG_ID_MAX];

    unsigned long mCount;

    unsigned long mTail;

    unsigned long mIndex;
@@ -67,7 +68,8 @@ public: 
        pthread_cond_signal(&threadTriggeredCondition);

    }



    void triggerSkip_Locked(unsigned int skip) { skipAhead = skip; }

    void triggerSkip_Locked(log_id_t id, unsigned int skip) { skipAhead[id] = skip; }

    void cleanSkip_Locked(void);



    // Called after LogTimeEntry removed from list, lock implicitly held

    void release_Locked(void) {
@@ -99,7 +101,7 @@ public: 
        // No one else is holding a reference to this

        delete this;

    }



    bool isWatching(log_id_t id) { return (mLogMask & (1<<id)) != 0; }

    // flushTo filter callbacks

    static bool FilterFirstPass(const LogBufferElement *element, void *me);

    static bool FilterSecondPass(const LogBufferElement *element, void *me);