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

Commit a2c02225 authored by Mark Salyzyn's avatar Mark Salyzyn
Browse files

logd: record multiple duplicate messages as chatty 

If a series of messages arrive from a single source with identical
message content payload, then suppress them and generate a chatty
report.  The checking is done on a per log id basis.

This alters the assumption that chatty messages are always at the
oldest entries, they now show up in the middle too.  To address this
change in behavior we print the first line, a chatty reference
which internally takes little space, then the last line in the series.

This does not conserve processing time in logd, and certainly has no
impact on the long path of formatting and submitting log messages from
from the source, but it may contribute to memory space and signal to
noise savings under heavy spammy loads.

Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Bug: 33535908
Change-Id: I3160c36d4f4e2f8216f528605a1b3993173f4dec
parent bb612a35

logd/LogAudit.cpp

+3 −1
Original line number Diff line number Diff line
@@ -34,6 +34,7 @@ 
#include "LogBuffer.h"

#include "LogKlog.h"

#include "LogReader.h"

#include "LogUtils.h"



#define KMSG_PRIORITY(PRI)                          \

    '<',                                            \
@@ -117,7 +118,8 @@ int LogAudit::logPrint(const char *fmt, ...) { 
            if (avcl) {

                char *avcr = strstr(str, avc);



                skip = avcr && !strcmp(avcl + strlen(avc), avcr + strlen(avc));

                skip = avcr && !fastcmp<strcmp>(avcl + strlen(avc),

                                                avcr + strlen(avc));

                if (skip) {

                    ++count;

                    free(last_str);

logd/LogBuffer.cpp

+104 −7
Original line number Diff line number Diff line
@@ -33,6 +33,7 @@ 
#include "LogBuffer.h"

#include "LogKlog.h"

#include "LogReader.h"

#include "LogUtils.h"



#ifndef __predict_false

#define __predict_false(exp) __builtin_expect((exp) != 0, 0)
@@ -110,9 +111,65 @@ LogBuffer::LogBuffer(LastLogTimes *times): 
        mTimes(*times) {

    pthread_mutex_init(&mLogElementsLock, NULL);



    log_id_for_each(i) {

        lastLoggedElements[i] = NULL;

        droppedElements[i] = NULL;

    }



    init();

}



LogBuffer::~LogBuffer() {

    log_id_for_each(i) {

        delete lastLoggedElements[i];

        delete droppedElements[i];

    }

}



static bool identical(LogBufferElement* elem, LogBufferElement* last) {

    // is it mostly identical?

//  if (!elem) return false;

    unsigned short lenl = elem->getMsgLen();

    if (!lenl) return false;

//  if (!last) return false;

    unsigned short lenr = last->getMsgLen();

    if (!lenr) return false;

//  if (elem->getLogId() != last->getLogId()) return false;

    if (elem->getUid() != last->getUid()) return false;

    if (elem->getPid() != last->getPid()) return false;

    if (elem->getTid() != last->getTid()) return false;



    // last is more than a minute old, stop squashing identical messages

    if (elem->getRealTime().nsec() >

        (last->getRealTime().nsec() + 60 * NS_PER_SEC)) return false;



    // Identical message

    const char* msgl = elem->getMsg();

    const char* msgr = last->getMsg();

    if ((lenl == lenr) && !fastcmp<memcmp>(msgl, msgr, lenl)) return true;



    // audit message (except sequence number) identical?

    static const char avc[] = "): avc: ";



    if (last->isBinary()) {

        if (fastcmp<memcmp>(msgl, msgr,

                            sizeof(android_log_event_string_t) -

                                sizeof(int32_t))) return false;

        msgl += sizeof(android_log_event_string_t);

        lenl -= sizeof(android_log_event_string_t);

        msgr += sizeof(android_log_event_string_t);

        lenr -= sizeof(android_log_event_string_t);

    }

    const char *avcl = android::strnstr(msgl, lenl, avc);

    if (!avcl) return false;

    lenl -= avcl - msgl;

    const char *avcr = android::strnstr(msgr, lenr, avc);

    if (!avcr) return false;

    lenr -= avcr - msgr;

    if (lenl != lenr) return false;

    return !fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), lenl);

}



int LogBuffer::log(log_id_t log_id, log_time realtime,

                   uid_t uid, pid_t pid, pid_t tid,

                   const char *msg, unsigned short len) {
@@ -145,14 +202,57 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, 
    }



    pthread_mutex_lock(&mLogElementsLock);

    LogBufferElement* currentLast = lastLoggedElements[log_id];

    if (currentLast) {

        LogBufferElement *dropped = droppedElements[log_id];

        unsigned short count = dropped ? dropped->getDropped() : 0;

        if (identical(elem, currentLast)) {

            if (dropped) {

                if (count == USHRT_MAX) {

                    log(dropped);

                    count = 1;

                } else {

                    delete dropped;

                    ++count;

                }

            }

            if (count) {

                stats.add(currentLast);

                stats.subtract(currentLast);

                currentLast->setDropped(count);

            }

            droppedElements[log_id] = currentLast;

            lastLoggedElements[log_id] = elem;

            pthread_mutex_unlock(&mLogElementsLock);

            return len;

        }

        if (dropped) {

            log(dropped);

            droppedElements[log_id] = NULL;

        }

        if (count) {

            log(currentLast);

        } else {

            delete currentLast;

        }

    }

    lastLoggedElements[log_id] = new LogBufferElement(*elem);



    log(elem);

    pthread_mutex_unlock(&mLogElementsLock);



    return len;

}



// assumes mLogElementsLock held, owns elem, will look after garbage collection

void LogBuffer::log(LogBufferElement* elem) {

    // Insert elements in time sorted order if possible

    //  NB: if end is region locked, place element at end of list

    LogBufferElementCollection::iterator it = mLogElements.end();

    LogBufferElementCollection::iterator last = it;

    while (last != mLogElements.begin()) {

        --it;

        if ((*it)->getRealTime() <= realtime) {

        if ((*it)->getRealTime() <= elem->getRealTime()) {

            break;

        }

        last = it;
@@ -194,10 +294,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, 
    }



    stats.add(elem);

    maybePrune(log_id);

    pthread_mutex_unlock(&mLogElementsLock);



    return len;

    maybePrune(elem->getLogId());

}



// Prune at most 10% of the log entries or maxPrune, whichever is less.

logd/LogBuffer.h

+5 −0
Original line number Diff line number Diff line
@@ -99,10 +99,15 @@ class LogBuffer { 


    bool monotonic;



    LogBufferElement* lastLoggedElements[LOG_ID_MAX];

    LogBufferElement* droppedElements[LOG_ID_MAX];

    void log(LogBufferElement* elem);



public:

    LastLogTimes &mTimes;



    explicit LogBuffer(LastLogTimes *times);

    ~LogBuffer();

    void init();

    bool isMonotonic() { return monotonic; }

logd/LogBufferElement.cpp

+13 −2
Original line number Diff line number Diff line
@@ -50,6 +50,19 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, 
        0;

}



LogBufferElement::LogBufferElement(const LogBufferElement &elem) :

        mTag(elem.mTag),

        mUid(elem.mUid),

        mPid(elem.mPid),

        mTid(elem.mTid),

        mSequence(elem.mSequence),

        mRealTime(elem.mRealTime),

        mMsgLen(elem.mMsgLen),

        mLogId(elem.mLogId) {

    mMsg = new char[mMsgLen];

    memcpy(mMsg, elem.mMsg, mMsgLen);

}



LogBufferElement::~LogBufferElement() {

    delete [] mMsg;

}
@@ -157,8 +170,6 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, 
                          mDropped, (mDropped > 1) ? "s" : "");



    size_t hdrLen;

    // LOG_ID_SECURITY not strictly needed since spam filter not activated,

    // but required for accuracy.

    if (isBinary()) {

        hdrLen = sizeof(android_log_event_string_t);

    } else {

logd/LogBufferElement.h

+2 −0
Original line number Diff line number Diff line
@@ -59,6 +59,7 @@ public: 
    LogBufferElement(log_id_t log_id, log_time realtime,

                     uid_t uid, pid_t pid, pid_t tid,

                     const char *msg, unsigned short len);

    LogBufferElement(const LogBufferElement &elem);

    virtual ~LogBufferElement();



    bool isBinary(void) const {
@@ -79,6 +80,7 @@ public: 
        return mDropped = value;

    }

    unsigned short getMsgLen() const { return mMsg ? mMsgLen : 0; }

    const char* getMsg() const { return mMsg; }

    uint64_t getSequence(void) const { return mSequence; }

    static uint64_t getCurrentSequence(void) { return sequence.load(memory_order_relaxed); }

    log_time getRealTime(void) const { return mRealTime; }