From b5b879678522882e6dbb02511379518d2b7b545d Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 23 Jan 2017 14:20:31 -0800 Subject: [PATCH] logd: multiple identical do not report expired Report multiple identical chatty messages differently than for regular expire chatty messages. Multiple identical will report identical count, while spam filter will report expire count. This should reduce the expected flood of people confused but chatty messages in continuous logcat output. Test: gTest logd_unit_tests --gtest_filter=logd.multiple* Change-Id: Iad93d3efc6a3938a4b87ccadddbd86626a015d44 --- logd/LogBuffer.cpp | 15 ++++++++++++++- logd/LogBufferElement.cpp | 17 +++++++++-------- logd/LogBufferElement.h | 8 +++++--- logd/tests/logd_test.cpp | 20 ++++++++++++++------ 4 files changed, 42 insertions(+), 18 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index cc65d4758..820ff64d1 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -1100,6 +1100,10 @@ uint64_t LogBuffer::flushTo( } } + // Help detect if the valid message before is from the same source so + // we can differentiate chatty filter types. + pid_t lastTid[LOG_ID_MAX] = { 0 }; + for (; it != mLogElements.end(); ++it) { LogBufferElement *element = *it; @@ -1126,10 +1130,19 @@ uint64_t LogBuffer::flushTo( } } + bool sameTid = lastTid[element->getLogId()] == element->getTid(); + // Dropped (chatty) immediately following a valid log from the + // same source in the same log buffer indicates we have a + // multiple identical squash. chatty that differs source + // is due to spam filter. chatty to chatty of different + // source is also due to spam filter. + lastTid[element->getLogId()] = (element->getDropped() && !sameTid) ? + 0 : element->getTid(); + pthread_mutex_unlock(&mLogElementsLock); // range locking in LastLogTimes looks after us - max = element->flushTo(reader, this, privileged); + max = element->flushTo(reader, this, privileged, sameTid); if (max == element->FLUSH_ERROR) { return max; diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index 5e37a30e8..a651fd4be 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -113,8 +113,8 @@ char *android::tidToName(pid_t tid) { } // assumption: mMsg == NULL -size_t LogBufferElement::populateDroppedMessage(char *&buffer, - LogBuffer *parent) { +size_t LogBufferElement::populateDroppedMessage(char*& buffer, + LogBuffer* parent, bool lastSame) { static const char tag[] = "chatty"; if (!__android_log_is_loggable_len(ANDROID_LOG_INFO, @@ -123,7 +123,7 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, return 0; } - static const char format_uid[] = "uid=%u%s%s expire %u line%s"; + static const char format_uid[] = "uid=%u%s%s %s %u line%s"; parent->lock(); const char *name = parent->uidToName(mUid); parent->unlock(); @@ -165,8 +165,9 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, } } // identical to below to calculate the buffer size required + const char* type = lastSame ? "identical" : "expire"; size_t len = snprintf(NULL, 0, format_uid, mUid, name ? name : "", - commName ? commName : "", + commName ? commName : "", type, mDropped, (mDropped > 1) ? "s" : ""); size_t hdrLen; @@ -198,7 +199,7 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, } snprintf(buffer + hdrLen, len + 1, format_uid, mUid, name ? name : "", - commName ? commName : "", + commName ? commName : "", type, mDropped, (mDropped > 1) ? "s" : ""); free(const_cast(name)); free(const_cast(commName)); @@ -206,8 +207,8 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, return retval; } -uint64_t LogBufferElement::flushTo(SocketClient *reader, LogBuffer *parent, - bool privileged) { +uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, + bool privileged, bool lastSame) { struct logger_entry_v4 entry; memset(&entry, 0, sizeof(struct logger_entry_v4)); @@ -229,7 +230,7 @@ uint64_t LogBufferElement::flushTo(SocketClient *reader, LogBuffer *parent, char *buffer = NULL; if (!mMsg) { - entry.len = populateDroppedMessage(buffer, parent); + entry.len = populateDroppedMessage(buffer, parent, lastSame); if (!entry.len) { return mSequence; } diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index f8ffacd7e..bd98b9c4b 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -53,8 +53,9 @@ class LogBufferElement { static atomic_int_fast64_t sequence; // assumption: mMsg == NULL - size_t populateDroppedMessage(char *&buffer, - LogBuffer *parent); + size_t populateDroppedMessage(char*& buffer, + LogBuffer* parent, + bool lastSame); public: LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, @@ -86,7 +87,8 @@ public: log_time getRealTime(void) const { return mRealTime; } static const uint64_t FLUSH_ERROR; - uint64_t flushTo(SocketClient *writer, LogBuffer *parent, bool privileged); + uint64_t flushTo(SocketClient* writer, LogBuffer* parent, + bool privileged, bool lastSame); }; #endif diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index 13a792286..2a6cdc8f5 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -853,11 +853,13 @@ void __android_log_btwrite_multiple__helper(int count) { int expected_count = (count < 2) ? count : 2; int expected_chatty_count = (count <= 2) ? 0 : 1; - int expected_expire_count = (count < 2) ? 0 : (count - 2); + int expected_identical_count = (count < 2) ? 0 : (count - 2); + static const int expected_expire_count = 0; count = 0; int second_count = 0; int chatty_count = 0; + int identical_count = 0; int expire_count = 0; for (;;) { @@ -887,11 +889,16 @@ void __android_log_btwrite_multiple__helper(int count) { ++chatty_count; // int len = get4LE(eventData + 4 + 1); log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0'; - const char *cp = strstr(eventData + 4 + 1 + 4, " expire "); - if (!cp) continue; - unsigned val = 0; - sscanf(cp, " expire %u lines", &val); - expire_count += val; + const char *cp; + if ((cp = strstr(eventData + 4 + 1 + 4, " identical "))) { + unsigned val = 0; + sscanf(cp, " identical %u lines", &val); + identical_count += val; + } else if ((cp = strstr(eventData + 4 + 1 + 4, " expire "))) { + unsigned val = 0; + sscanf(cp, " expire %u lines", &val); + expire_count += val; + } } } @@ -900,6 +907,7 @@ void __android_log_btwrite_multiple__helper(int count) { EXPECT_EQ(expected_count, count); EXPECT_EQ(1, second_count); EXPECT_EQ(expected_chatty_count, chatty_count); + EXPECT_EQ(expected_identical_count, identical_count); EXPECT_EQ(expected_expire_count, expire_count); }