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
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index cc65d47..820ff64 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -1100,6 +1100,10 @@
}
}
+ // 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 @@
}
}
+ 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 5e37a30..a651fd4 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -113,8 +113,8 @@
}
// 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 @@
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 @@
}
}
// 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 @@
}
snprintf(buffer + hdrLen, len + 1, format_uid, mUid, name ? name : "",
- commName ? commName : "",
+ commName ? commName : "", type,
mDropped, (mDropped > 1) ? "s" : "");
free(const_cast<char *>(name));
free(const_cast<char *>(commName));
@@ -206,8 +207,8 @@
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 @@
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 f8ffacd..bd98b9c 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -53,8 +53,9 @@
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 @@
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 13a7922..2a6cdc8 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -853,11 +853,13 @@
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 @@
++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 @@
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);
}