Merge "Update TEST_MAPPING."
diff --git a/adb/daemon/shell_service.cpp b/adb/daemon/shell_service.cpp
index fbfae1e..dbca4ad 100644
--- a/adb/daemon/shell_service.cpp
+++ b/adb/daemon/shell_service.cpp
@@ -646,15 +646,21 @@
}
// After handling all of the events we've received, check to see if any fds have died.
- if (stdinout_pfd.revents & (POLLHUP | POLLRDHUP | POLLERR | POLLNVAL)) {
+ auto poll_finished = [](int events) {
+ // Don't return failure until we've read out all of the fd's incoming data.
+ return (events & POLLIN) == 0 &&
+ (events & (POLLHUP | POLLRDHUP | POLLERR | POLLNVAL)) != 0;
+ };
+
+ if (poll_finished(stdinout_pfd.revents)) {
return &stdinout_sfd_;
}
- if (stderr_pfd.revents & (POLLHUP | POLLRDHUP | POLLERR | POLLNVAL)) {
+ if (poll_finished(stderr_pfd.revents)) {
return &stderr_sfd_;
}
- if (protocol_pfd.revents & (POLLHUP | POLLRDHUP | POLLERR | POLLNVAL)) {
+ if (poll_finished(protocol_pfd.revents)) {
return &protocol_sfd_;
}
} // while (!dead_sfd)
diff --git a/adb/daemon/usb.cpp b/adb/daemon/usb.cpp
index 7fff05a..a663871 100644
--- a/adb/daemon/usb.cpp
+++ b/adb/daemon/usb.cpp
@@ -231,7 +231,14 @@
offset += write_size;
}
}
- SubmitWrites();
+
+ // Wake up the worker thread to submit writes.
+ uint64_t notify = 1;
+ ssize_t rc = adb_write(worker_event_fd_.get(), ¬ify, sizeof(notify));
+ if (rc < 0) {
+ PLOG(FATAL) << "failed to notify worker eventfd to submit writes";
+ }
+
return true;
}
@@ -443,6 +450,9 @@
}
ReadEvents();
+
+ std::lock_guard<std::mutex> lock(write_mutex_);
+ SubmitWrites();
}
});
}
@@ -626,8 +636,6 @@
write_requests_.erase(it);
size_t outstanding_writes = --writes_submitted_;
LOG(DEBUG) << "USB write: reaped, down to " << outstanding_writes;
-
- SubmitWrites();
}
IoWriteBlock CreateWriteBlock(std::shared_ptr<Block> payload, size_t offset, size_t len,
diff --git a/adb/test_device.py b/adb/test_device.py
index f5e4cbb..9f1f403 100755
--- a/adb/test_device.py
+++ b/adb/test_device.py
@@ -82,10 +82,13 @@
class AbbTest(DeviceTest):
def test_smoke(self):
- result = subprocess.run(['adb', 'abb'], capture_output=True)
- self.assertEqual(1, result.returncode)
- expected_output = b"cmd: No service specified; use -l to list all services\n"
- self.assertEqual(expected_output, result.stderr)
+ abb = subprocess.run(['adb', 'abb'], capture_output=True)
+ cmd = subprocess.run(['adb', 'shell', 'cmd'], capture_output=True)
+
+ # abb squashes all failures to 1.
+ self.assertEqual(abb.returncode == 0, cmd.returncode == 0)
+ self.assertEqual(abb.stdout, cmd.stdout)
+ self.assertEqual(abb.stderr, cmd.stderr)
class ForwardReverseTest(DeviceTest):
def _test_no_rebind(self, description, direction_list, direction,
diff --git a/fs_mgr/fs_mgr.cpp b/fs_mgr/fs_mgr.cpp
index d2daaa1..8c2e001 100644
--- a/fs_mgr/fs_mgr.cpp
+++ b/fs_mgr/fs_mgr.cpp
@@ -454,7 +454,8 @@
<< entry.encryption_options;
return;
}
- if ((options.flags & FSCRYPT_POLICY_FLAG_IV_INO_LBLK_64) != 0) {
+ if ((options.flags &
+ (FSCRYPT_POLICY_FLAG_IV_INO_LBLK_64 | FSCRYPT_POLICY_FLAG_IV_INO_LBLK_32)) != 0) {
// We can only use this policy on ext4 if the "stable_inodes" feature
// is set on the filesystem, otherwise shrinking will break encrypted files.
if ((sb->s_feature_compat & cpu_to_le32(EXT4_FEATURE_COMPAT_STABLE_INODES)) == 0) {
diff --git a/fs_mgr/libsnapshot/Android.bp b/fs_mgr/libsnapshot/Android.bp
index 2783e4d..95301ff 100644
--- a/fs_mgr/libsnapshot/Android.bp
+++ b/fs_mgr/libsnapshot/Android.bp
@@ -248,10 +248,6 @@
cc_defaults {
name: "libsnapshot_fuzzer_defaults",
-
- // TODO(b/154633114): make host supported.
- // host_supported: true,
-
native_coverage : true,
srcs: [
// Compile the protobuf definition again with type full.
diff --git a/logd/Android.bp b/logd/Android.bp
index 7e58f07..5e591d9 100644
--- a/logd/Android.bp
+++ b/logd/Android.bp
@@ -125,10 +125,7 @@
"-Wextra",
"-Werror",
"-fno-builtin",
-
- "-DAUDITD_LOG_TAG=1003",
- "-DCHATTY_LOG_TAG=1004",
- ],
+ ] + event_flag,
srcs: [
"logd_test.cpp",
diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp
index 9e08e9d..fd2c236 100644
--- a/logd/ChattyLogBuffer.cpp
+++ b/logd/ChattyLogBuffer.cpp
@@ -28,6 +28,7 @@
#include <time.h>
#include <unistd.h>
+#include <limits>
#include <unordered_map>
#include <utility>
@@ -58,29 +59,17 @@
ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune,
LogStatistics* stats)
: reader_list_(reader_list), tags_(tags), prune_(prune), stats_(stats) {
- pthread_rwlock_init(&mLogElementsLock, nullptr);
-
- log_id_for_each(i) {
- lastLoggedElements[i] = nullptr;
- droppedElements[i] = nullptr;
- }
-
Init();
}
-ChattyLogBuffer::~ChattyLogBuffer() {
- log_id_for_each(i) {
- delete lastLoggedElements[i];
- delete droppedElements[i];
- }
-}
+ChattyLogBuffer::~ChattyLogBuffer() {}
LogBufferElementCollection::iterator ChattyLogBuffer::GetOldest(log_id_t log_id) {
auto it = mLogElements.begin();
if (oldest_[log_id]) {
it = *oldest_[log_id];
}
- while (it != mLogElements.end() && (*it)->getLogId() != log_id) {
+ while (it != mLogElements.end() && it->getLogId() != log_id) {
it++;
}
if (it != mLogElements.end()) {
@@ -146,33 +135,20 @@
return SAME;
}
-int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
- const char* msg, uint16_t len) {
- if (log_id >= LOG_ID_MAX) {
- 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);
-
- // b/137093665: don't coalesce security messages.
+bool ChattyLogBuffer::ShouldLog(log_id_t log_id, const char* msg, uint16_t len) {
if (log_id == LOG_ID_SECURITY) {
- wrlock();
- log(elem);
- unlock();
-
- return len;
+ return true;
}
int prio = ANDROID_LOG_INFO;
const char* tag = nullptr;
size_t tag_len = 0;
if (log_id == LOG_ID_EVENTS || log_id == LOG_ID_STATS) {
- tag = tags_->tagToName(elem->getTag());
+ if (len < sizeof(android_event_header_t)) {
+ return false;
+ }
+ int32_t numeric_tag = reinterpret_cast<const android_event_header_t*>(msg)->tag;
+ tag = tags_->tagToName(numeric_tag);
if (tag) {
tag_len = strlen(tag);
}
@@ -181,169 +157,112 @@
tag = msg + 1;
tag_len = strnlen(tag, len - 1);
}
- if (!__android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE)) {
+ return __android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE);
+}
+
+int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
+ const char* msg, uint16_t len) {
+ if (log_id >= LOG_ID_MAX) {
+ return -EINVAL;
+ }
+
+ if (!ShouldLog(log_id, msg, len)) {
// Log traffic received to total
- stats_->AddTotal(elem);
- delete elem;
+ stats_->AddTotal(log_id, len);
return -EACCES;
}
- wrlock();
- LogBufferElement* currentLast = lastLoggedElements[log_id];
- if (currentLast) {
- LogBufferElement* dropped = droppedElements[log_id];
- uint16_t count = dropped ? dropped->getDropped() : 0;
- //
- // State Init
- // incoming:
- // dropped = nullptr
- // currentLast = nullptr;
- // elem = incoming message
- // outgoing:
- // dropped = nullptr -> State 0
- // currentLast = copy of elem
- // log elem
- // State 0
- // incoming:
- // count = 0
- // dropped = nullptr
- // currentLast = copy of last message
- // elem = incoming message
- // outgoing: if match != DIFFERENT
- // dropped = copy of first identical message -> State 1
- // currentLast = reference to elem
- // break: if match == DIFFERENT
- // dropped = nullptr -> State 0
- // delete copy of last message (incoming currentLast)
- // currentLast = copy of elem
- // log elem
- // State 1
- // incoming:
- // count = 0
- // dropped = copy of first identical message
- // currentLast = reference to last held-back incoming
- // message
- // elem = incoming message
- // outgoing: if match == SAME
- // delete copy of first identical message (dropped)
- // dropped = reference to last held-back incoming
- // message set to chatty count of 1 -> State 2
- // currentLast = reference to elem
- // outgoing: if match == SAME_LIBLOG
- // dropped = copy of first identical message -> State 1
- // take sum of currentLast and elem
- // if sum overflows:
- // log currentLast
- // currentLast = reference to elem
- // else
- // delete currentLast
- // currentLast = reference to elem, sum liblog.
- // break: if match == DIFFERENT
- // delete dropped
- // dropped = nullptr -> State 0
- // log reference to last held-back (currentLast)
- // currentLast = copy of elem
- // log elem
- // State 2
- // incoming:
- // count = chatty count
- // dropped = chatty message holding count
- // currentLast = reference to last held-back incoming
- // message.
- // dropped = chatty message holding count
- // elem = incoming message
- // outgoing: if match != DIFFERENT
- // delete chatty message holding count
- // dropped = reference to last held-back incoming
- // message, set to chatty count + 1
- // currentLast = reference to elem
- // break: if match == DIFFERENT
- // log dropped (chatty message)
- // dropped = nullptr -> State 0
- // log reference to last held-back (currentLast)
- // currentLast = copy of elem
- // log elem
- //
- enum match_type match = identical(elem, currentLast);
- if (match != DIFFERENT) {
- if (dropped) {
- // Sum up liblog tag messages?
- if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) {
- android_log_event_int_t* event = reinterpret_cast<android_log_event_int_t*>(
- const_cast<char*>(currentLast->getMsg()));
- //
- // To unit test, differentiate with something like:
- // event->header.tag = htole32(CHATTY_LOG_TAG);
- // here, then instead of delete currentLast below,
- // log(currentLast) to see the incremental sums form.
- //
- uint32_t swab = event->payload.data;
- unsigned long long total = htole32(swab);
- event = reinterpret_cast<android_log_event_int_t*>(
- const_cast<char*>(elem->getMsg()));
- swab = event->payload.data;
+ // 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;
- lastLoggedElements[LOG_ID_EVENTS] = elem;
- total += htole32(swab);
- // check for overflow
- if (total >= UINT32_MAX) {
- log(currentLast);
- unlock();
- return len;
- }
- stats_->AddTotal(currentLast);
- delete currentLast;
- swab = total;
- event->payload.data = htole32(swab);
- unlock();
- return len;
- }
- if (count == USHRT_MAX) {
- log(dropped);
- count = 1;
- } else {
- delete dropped;
- ++count;
- }
+ LogBufferElement elem(log_id, realtime, uid, pid, tid, msg, len);
+
+ // b/137093665: don't coalesce security messages.
+ if (log_id == LOG_ID_SECURITY) {
+ auto lock = std::lock_guard{lock_};
+ Log(std::move(elem));
+ return len;
+ }
+
+ auto lock = std::lock_guard{lock_};
+ // Initialize last_logged_elements_ to a copy of elem if logging the first element for a log_id.
+ if (!last_logged_elements_[log_id]) {
+ last_logged_elements_[log_id].emplace(elem);
+ Log(std::move(elem));
+ return len;
+ }
+
+ LogBufferElement& current_last = *last_logged_elements_[log_id];
+ enum match_type match = identical(&elem, ¤t_last);
+
+ if (match == DIFFERENT) {
+ if (duplicate_elements_[log_id]) {
+ // If we previously had 3+ identical messages, log the chatty message.
+ if (duplicate_elements_[log_id]->getDropped() > 0) {
+ Log(std::move(*duplicate_elements_[log_id]));
}
- if (count) {
- stats_->AddTotal(currentLast);
- currentLast->setDropped(count);
- }
- droppedElements[log_id] = currentLast;
- lastLoggedElements[log_id] = elem;
- unlock();
+ duplicate_elements_[log_id].reset();
+ // Log the saved copy of the last identical message seen.
+ Log(std::move(current_last));
+ }
+ last_logged_elements_[log_id].emplace(elem);
+ Log(std::move(elem));
+ return len;
+ }
+
+ // 2 identical message: set duplicate_elements_ appropriately.
+ if (!duplicate_elements_[log_id]) {
+ duplicate_elements_[log_id].emplace(std::move(current_last));
+ last_logged_elements_[log_id].emplace(std::move(elem));
+ return len;
+ }
+
+ // 3+ identical LIBLOG event messages: coalesce them into last_logged_elements_.
+ if (match == SAME_LIBLOG) {
+ const android_log_event_int_t* current_last_event =
+ reinterpret_cast<const android_log_event_int_t*>(current_last.getMsg());
+ int64_t current_last_count = current_last_event->payload.data;
+ android_log_event_int_t* elem_event =
+ reinterpret_cast<android_log_event_int_t*>(const_cast<char*>(elem.getMsg()));
+ int64_t elem_count = elem_event->payload.data;
+
+ int64_t total = current_last_count + elem_count;
+ if (total > std::numeric_limits<int32_t>::max()) {
+ Log(std::move(current_last));
+ last_logged_elements_[log_id].emplace(std::move(elem));
return len;
}
- if (dropped) { // State 1 or 2
- if (count) { // State 2
- log(dropped); // report chatty
- } else { // State 1
- delete dropped;
- }
- droppedElements[log_id] = nullptr;
- log(currentLast); // report last message in the series
- } else { // State 0
- delete currentLast;
- }
+ stats_->AddTotal(current_last.getLogId(), current_last.getMsgLen());
+ elem_event->payload.data = total;
+ last_logged_elements_[log_id].emplace(std::move(elem));
+ return len;
}
- lastLoggedElements[log_id] = new LogBufferElement(*elem);
- log(elem);
- unlock();
-
+ // 3+ identical messages (not LIBLOG) messages: increase the drop count.
+ uint16_t dropped_count = duplicate_elements_[log_id]->getDropped();
+ if (dropped_count == std::numeric_limits<uint16_t>::max()) {
+ Log(std::move(*duplicate_elements_[log_id]));
+ dropped_count = 0;
+ }
+ // We're dropping the current_last log so add its stats to the total.
+ stats_->AddTotal(current_last.getLogId(), current_last.getMsgLen());
+ // Use current_last for tracking the dropped count to always use the latest timestamp.
+ current_last.setDropped(dropped_count + 1);
+ duplicate_elements_[log_id].emplace(std::move(current_last));
+ last_logged_elements_[log_id].emplace(std::move(elem));
return len;
}
-// assumes ChattyLogBuffer::wrlock() held, owns elem, look after garbage collection
-void ChattyLogBuffer::log(LogBufferElement* elem) {
- mLogElements.push_back(elem);
- stats_->Add(elem);
- maybePrune(elem->getLogId());
- reader_list_->NotifyNewLog(1 << elem->getLogId());
+void ChattyLogBuffer::Log(LogBufferElement&& elem) {
+ log_id_t log_id = elem.getLogId();
+ mLogElements.push_back(std::move(elem));
+ stats_->Add(&mLogElements.back());
+ maybePrune(log_id);
+ reader_list_->NotifyNewLog(1 << log_id);
}
-// ChattyLogBuffer::wrlock() must be held when this function is called.
void ChattyLogBuffer::maybePrune(log_id_t id) {
unsigned long prune_rows;
if (stats_->ShouldPrune(id, log_buffer_size(id), &prune_rows)) {
@@ -353,15 +272,15 @@
LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementCollection::iterator it,
bool coalesce) {
- LogBufferElement* element = *it;
- log_id_t id = element->getLogId();
+ LogBufferElement& element = *it;
+ log_id_t id = element.getLogId();
// Remove iterator references in the various lists that will become stale
// after the element is erased from the main logging list.
{ // start of scope for found iterator
- int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag()
- : element->getUid();
+ int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element.getTag()
+ : element.getUid();
LogBufferIteratorMap::iterator found = mLastWorst[id].find(key);
if ((found != mLastWorst[id].end()) && (it == found->second)) {
mLastWorst[id].erase(found);
@@ -372,7 +291,7 @@
// element->getUid() may not be AID_SYSTEM for next-best-watermark.
// will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and
// long term code stability, find() check should be fast for those ids.
- LogBufferPidIteratorMap::iterator found = mLastWorstPidOfSystem[id].find(element->getPid());
+ LogBufferPidIteratorMap::iterator found = mLastWorstPidOfSystem[id].find(element.getPid());
if (found != mLastWorstPidOfSystem[id].end() && it == found->second) {
mLastWorstPidOfSystem[id].erase(found);
}
@@ -386,7 +305,15 @@
int key =
(id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() : element->getUid();
#endif
+
+ if (coalesce) {
+ stats_->Erase(&element);
+ } else {
+ stats_->Subtract(&element);
+ }
+
it = mLogElements.erase(it);
+
if (doSetLast) {
log_id_for_each(i) {
if (setLast[i]) {
@@ -413,13 +340,6 @@
}
}
#endif
- if (coalesce) {
- stats_->Erase(element);
- } else {
- stats_->Subtract(element);
- }
- delete element;
-
return it;
}
@@ -539,8 +459,6 @@
// The third thread is optional, and only gets hit if there was a whitelist
// and more needs to be pruned against the backstop of the region lock.
//
-// ChattyLogBuffer::wrlock() must be held when this function is called.
-//
bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
LogReaderThread* oldest = nullptr;
bool busy = false;
@@ -567,14 +485,14 @@
// filter logistics is not required.
it = GetOldest(id);
while (it != mLogElements.end()) {
- LogBufferElement* element = *it;
+ LogBufferElement& element = *it;
- if (element->getLogId() != id || element->getUid() != caller_uid) {
+ if (element.getLogId() != id || element.getUid() != caller_uid) {
++it;
continue;
}
- if (oldest && oldest->start() <= element->getSequence()) {
+ if (oldest && oldest->start() <= element.getSequence()) {
busy = true;
kickMe(oldest, id, pruneRows);
break;
@@ -654,21 +572,21 @@
--lastt;
LogBufferElementLast last;
while (it != mLogElements.end()) {
- LogBufferElement* element = *it;
+ LogBufferElement& element = *it;
- if (oldest && oldest->start() <= element->getSequence()) {
+ if (oldest && oldest->start() <= element.getSequence()) {
busy = true;
// Do not let chatty eliding trigger any reader mitigation
break;
}
- if (element->getLogId() != id) {
+ if (element.getLogId() != id) {
++it;
continue;
}
// below this point element->getLogId() == id
- uint16_t dropped = element->getDropped();
+ uint16_t dropped = element.getDropped();
// remove any leading drops
if (leading && dropped) {
@@ -676,16 +594,16 @@
continue;
}
- if (dropped && last.coalesce(element, dropped)) {
+ if (dropped && last.coalesce(&element, dropped)) {
it = erase(it, true);
continue;
}
- int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag()
- : element->getUid();
+ int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element.getTag()
+ : element.getUid();
- if (hasBlacklist && prune_->naughty(element)) {
- last.clear(element);
+ if (hasBlacklist && prune_->naughty(&element)) {
+ last.clear(&element);
it = erase(it);
if (dropped) {
continue;
@@ -701,25 +619,25 @@
if (worst_sizes < second_worst_sizes) {
break;
}
- worst_sizes -= element->getMsgLen();
+ worst_sizes -= element.getMsgLen();
}
continue;
}
- if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old)) ||
- (element->getRealTime() > (*lastt)->getRealTime())) {
+ if (element.getRealTime() < (lastt->getRealTime() - too_old) ||
+ element.getRealTime() > lastt->getRealTime()) {
break;
}
if (dropped) {
- last.add(element);
- if (worstPid && ((!gc && element->getPid() == worstPid) ||
- mLastWorstPidOfSystem[id].find(element->getPid()) ==
+ last.add(&element);
+ if (worstPid && ((!gc && element.getPid() == worstPid) ||
+ mLastWorstPidOfSystem[id].find(element.getPid()) ==
mLastWorstPidOfSystem[id].end())) {
// element->getUid() may not be AID_SYSTEM, next best
// watermark if current one empty. id is not LOG_ID_EVENTS
// or LOG_ID_SECURITY because of worstPid check.
- mLastWorstPidOfSystem[id][element->getPid()] = it;
+ mLastWorstPidOfSystem[id][element.getPid()] = it;
}
if ((!gc && !worstPid && (key == worst)) ||
(mLastWorst[id].find(key) == mLastWorst[id].end())) {
@@ -729,9 +647,9 @@
continue;
}
- if (key != worst || (worstPid && element->getPid() != worstPid)) {
+ if (key != worst || (worstPid && element.getPid() != worstPid)) {
leading = false;
- last.clear(element);
+ last.clear(&element);
++it;
continue;
}
@@ -745,18 +663,18 @@
kick = true;
- uint16_t len = element->getMsgLen();
+ uint16_t len = element.getMsgLen();
// do not create any leading drops
if (leading) {
it = erase(it);
} else {
- stats_->Drop(element);
- element->setDropped(1);
- if (last.coalesce(element, 1)) {
+ stats_->Drop(&element);
+ element.setDropped(1);
+ if (last.coalesce(&element, 1)) {
it = erase(it, true);
} else {
- last.add(element);
+ last.add(&element);
if (worstPid && (!gc || mLastWorstPidOfSystem[id].find(worstPid) ==
mLastWorstPidOfSystem[id].end())) {
// element->getUid() may not be AID_SYSTEM, next best
@@ -786,20 +704,20 @@
bool hasWhitelist = (id != LOG_ID_SECURITY) && prune_->nice() && !clearAll;
it = GetOldest(id);
while ((pruneRows > 0) && (it != mLogElements.end())) {
- LogBufferElement* element = *it;
+ LogBufferElement& element = *it;
- if (element->getLogId() != id) {
+ if (element.getLogId() != id) {
it++;
continue;
}
- if (oldest && oldest->start() <= element->getSequence()) {
+ if (oldest && oldest->start() <= element.getSequence()) {
busy = true;
if (!whitelist) kickMe(oldest, id, pruneRows);
break;
}
- if (hasWhitelist && !element->getDropped() && prune_->nice(element)) {
+ if (hasWhitelist && !element.getDropped() && prune_->nice(&element)) {
// WhiteListed
whitelist = true;
it++;
@@ -814,14 +732,14 @@
if (whitelist && (pruneRows > 0)) {
it = GetOldest(id);
while ((it != mLogElements.end()) && (pruneRows > 0)) {
- LogBufferElement* element = *it;
+ LogBufferElement& element = *it;
- if (element->getLogId() != id) {
+ if (element.getLogId() != id) {
++it;
continue;
}
- if (oldest && oldest->start() <= element->getSequence()) {
+ if (oldest && oldest->start() <= element.getSequence()) {
busy = true;
kickMe(oldest, id, pruneRows);
break;
@@ -845,9 +763,10 @@
// one entry, not another clear run, so we are looking for
// the quick side effect of the return value to tell us if
// we have a _blocked_ reader.
- wrlock();
- busy = prune(id, 1, uid);
- unlock();
+ {
+ auto lock = std::lock_guard{lock_};
+ busy = prune(id, 1, uid);
+ }
// It is still busy, blocked reader(s), lets kill them all!
// otherwise, lets be a good citizen and preserve the slow
// readers and let the clear run (below) deal with determining
@@ -864,9 +783,10 @@
}
}
}
- wrlock();
- busy = prune(id, ULONG_MAX, uid);
- unlock();
+ {
+ auto lock = std::lock_guard{lock_};
+ busy = prune(id, ULONG_MAX, uid);
+ }
if (!busy || !--retry) {
break;
}
@@ -881,17 +801,15 @@
if (!__android_logger_valid_buffer_size(size)) {
return -1;
}
- wrlock();
+ auto lock = std::lock_guard{lock_};
log_buffer_size(id) = size;
- unlock();
return 0;
}
// get the total space allocated to "id"
unsigned long ChattyLogBuffer::GetSize(log_id_t id) {
- rdlock();
+ auto shared_lock = SharedLock{lock_};
size_t retval = log_buffer_size(id);
- unlock();
return retval;
}
@@ -901,7 +819,7 @@
LogBufferElementCollection::iterator it;
uid_t uid = writer->uid();
- rdlock();
+ auto shared_lock = SharedLock{lock_};
if (start <= 1) {
// client wants to start from the beginning
@@ -912,8 +830,7 @@
for (it = mLogElements.end(); it != mLogElements.begin();
/* do nothing */) {
--it;
- LogBufferElement* element = *it;
- if (element->getSequence() <= start) {
+ if (it->getSequence() <= start) {
it++;
break;
}
@@ -923,19 +840,19 @@
uint64_t curr = start;
for (; it != mLogElements.end(); ++it) {
- LogBufferElement* element = *it;
+ LogBufferElement& element = *it;
- if (!writer->privileged() && element->getUid() != uid) {
+ if (!writer->privileged() && element.getUid() != uid) {
continue;
}
- if (!writer->can_read_security_logs() && element->getLogId() == LOG_ID_SECURITY) {
+ if (!writer->can_read_security_logs() && element.getLogId() == LOG_ID_SECURITY) {
continue;
}
// NB: calling out to another object with wrlock() held (safe)
if (filter) {
- FlushToResult ret = filter(element);
+ FlushToResult ret = filter(&element);
if (ret == FlushToResult::kSkip) {
continue;
}
@@ -946,27 +863,24 @@
bool sameTid = false;
if (lastTid) {
- sameTid = lastTid[element->getLogId()] == element->getTid();
+ 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();
+ lastTid[element.getLogId()] = (element.getDropped() && !sameTid) ? 0 : element.getTid();
}
- unlock();
+ shared_lock.unlock();
- curr = element->getSequence();
+ curr = element.getSequence();
// range locking in LastLogTimes looks after us
- if (!element->FlushTo(writer, stats_, sameTid)) {
+ if (!element.FlushTo(writer, stats_, sameTid)) {
return FLUSH_ERROR;
}
- rdlock();
+ shared_lock.lock_shared();
}
- unlock();
-
return curr;
}
diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h
index 29a421d..08c4bff 100644
--- a/logd/ChattyLogBuffer.h
+++ b/logd/ChattyLogBuffer.h
@@ -22,6 +22,7 @@
#include <optional>
#include <string>
+#include <android-base/thread_annotations.h>
#include <android/log.h>
#include <private/android_filesystem_config.h>
#include <sysutils/SocketClient.h>
@@ -34,25 +35,21 @@
#include "LogTags.h"
#include "LogWhiteBlackList.h"
#include "LogWriter.h"
+#include "rwlock.h"
-typedef std::list<LogBufferElement*> LogBufferElementCollection;
+typedef std::list<LogBufferElement> LogBufferElementCollection;
class ChattyLogBuffer : public LogBuffer {
- LogBufferElementCollection mLogElements;
- pthread_rwlock_t mLogElementsLock;
+ LogBufferElementCollection mLogElements GUARDED_BY(lock_);
// watermark of any worst/chatty uid processing
typedef std::unordered_map<uid_t, LogBufferElementCollection::iterator> LogBufferIteratorMap;
- LogBufferIteratorMap mLastWorst[LOG_ID_MAX];
+ LogBufferIteratorMap mLastWorst[LOG_ID_MAX] GUARDED_BY(lock_);
// watermark of any worst/chatty pid of system processing
typedef std::unordered_map<pid_t, LogBufferElementCollection::iterator> LogBufferPidIteratorMap;
- LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX];
+ LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX] GUARDED_BY(lock_);
- unsigned long mMaxSize[LOG_ID_MAX];
-
- LogBufferElement* lastLoggedElements[LOG_ID_MAX];
- LogBufferElement* droppedElements[LOG_ID_MAX];
- void log(LogBufferElement* elem);
+ unsigned long mMaxSize[LOG_ID_MAX] GUARDED_BY(lock_);
public:
ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune,
@@ -71,20 +68,18 @@
int SetSize(log_id_t id, unsigned long size) override;
private:
- void wrlock() { pthread_rwlock_wrlock(&mLogElementsLock); }
- void rdlock() { pthread_rwlock_rdlock(&mLogElementsLock); }
- void unlock() { pthread_rwlock_unlock(&mLogElementsLock); }
+ void maybePrune(log_id_t id) REQUIRES(lock_);
+ void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows) REQUIRES_SHARED(lock_);
- void maybePrune(log_id_t id);
- void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows);
-
- bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);
+ bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT) REQUIRES(lock_);
LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it,
- bool coalesce = false);
+ bool coalesce = false) REQUIRES(lock_);
+ bool ShouldLog(log_id_t log_id, const char* msg, uint16_t len);
+ void Log(LogBufferElement&& elem) REQUIRES(lock_);
// Returns an iterator to the oldest element for a given log type, or mLogElements.end() if
// there are no logs for the given log type. Requires mLogElementsLock to be held.
- LogBufferElementCollection::iterator GetOldest(log_id_t log_id);
+ LogBufferElementCollection::iterator GetOldest(log_id_t log_id) REQUIRES(lock_);
LogReaderList* reader_list_;
LogTags* tags_;
@@ -94,4 +89,12 @@
// Keeps track of the iterator to the oldest log message of a given log type, as an
// optimization when pruning logs. Use GetOldest() to retrieve.
std::optional<LogBufferElementCollection::iterator> oldest_[LOG_ID_MAX];
+
+ RwLock lock_;
+
+ // This always contains a copy of the last message logged, for deduplication.
+ std::optional<LogBufferElement> last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_);
+ // This contains an element if duplicate messages are seen.
+ // Its `dropped` count is `duplicates seen - 1`.
+ std::optional<LogBufferElement> duplicate_elements_[LOG_ID_MAX] GUARDED_BY(lock_);
};
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index 4f5cabd..3bcf11d 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -63,6 +63,23 @@
}
}
+LogBufferElement::LogBufferElement(LogBufferElement&& elem)
+ : mUid(elem.mUid),
+ mPid(elem.mPid),
+ mTid(elem.mTid),
+ mSequence(elem.mSequence),
+ mRealTime(elem.mRealTime),
+ mMsgLen(elem.mMsgLen),
+ mLogId(elem.mLogId),
+ mDropped(elem.mDropped) {
+ if (mDropped) {
+ mTag = elem.getTag();
+ } else {
+ mMsg = elem.mMsg;
+ elem.mMsg = nullptr;
+ }
+}
+
LogBufferElement::~LogBufferElement() {
if (!mDropped) {
delete[] mMsg;
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index 2f2d70d..a777970 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -60,6 +60,7 @@
LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
pid_t tid, const char* msg, uint16_t len);
LogBufferElement(const LogBufferElement& elem);
+ LogBufferElement(LogBufferElement&& elem);
~LogBufferElement();
bool isBinary(void) const {
diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp
index cc3cb76..b52ce8f 100644
--- a/logd/LogBufferTest.cpp
+++ b/logd/LogBufferTest.cpp
@@ -18,7 +18,9 @@
#include <unistd.h>
+#include <limits>
#include <memory>
+#include <regex>
#include <vector>
#include <android-base/stringprintf.h>
@@ -34,6 +36,7 @@
#include "LogWriter.h"
using android::base::Join;
+using android::base::Split;
using android::base::StringPrintf;
#ifndef __ANDROID__
@@ -58,12 +61,148 @@
return nullptr;
}
+struct LogMessage {
+ logger_entry entry;
+ std::string message;
+ bool regex_compare = false; // Only set for expected messages, when true 'message' should be
+ // interpretted as a regex.
+};
+
+std::vector<std::string> CompareLoggerEntries(const logger_entry& expected,
+ const logger_entry& result, bool ignore_len) {
+ std::vector<std::string> errors;
+ if (!ignore_len && expected.len != result.len) {
+ errors.emplace_back(
+ StringPrintf("len: expected %" PRIu16 " vs %" PRIu16, expected.len, result.len));
+ }
+ if (expected.hdr_size != result.hdr_size) {
+ errors.emplace_back(StringPrintf("hdr_size: %" PRIu16 " vs %" PRIu16, expected.hdr_size,
+ result.hdr_size));
+ }
+ if (expected.pid != result.pid) {
+ errors.emplace_back(
+ StringPrintf("pid: expected %" PRIi32 " vs %" PRIi32, expected.pid, result.pid));
+ }
+ if (expected.tid != result.tid) {
+ errors.emplace_back(
+ StringPrintf("tid: expected %" PRIu32 " vs %" PRIu32, expected.tid, result.tid));
+ }
+ if (expected.sec != result.sec) {
+ errors.emplace_back(
+ StringPrintf("sec: expected %" PRIu32 " vs %" PRIu32, expected.sec, result.sec));
+ }
+ if (expected.nsec != result.nsec) {
+ errors.emplace_back(
+ StringPrintf("nsec: expected %" PRIu32 " vs %" PRIu32, expected.nsec, result.nsec));
+ }
+ if (expected.lid != result.lid) {
+ errors.emplace_back(
+ StringPrintf("lid: expected %" PRIu32 " vs %" PRIu32, expected.lid, result.lid));
+ }
+ if (expected.uid != result.uid) {
+ errors.emplace_back(
+ StringPrintf("uid: expected %" PRIu32 " vs %" PRIu32, expected.uid, result.uid));
+ }
+ return errors;
+}
+
+std::string MakePrintable(std::string in) {
+ if (in.size() > 80) {
+ in = in.substr(0, 80) + "...";
+ }
+ std::string result;
+ for (const char c : in) {
+ if (isprint(c)) {
+ result.push_back(c);
+ } else {
+ result.append(StringPrintf("\\%02x", static_cast<int>(c) & 0xFF));
+ }
+ }
+ return result;
+}
+
+std::string CompareMessages(const std::string& expected, const std::string& result) {
+ if (expected == result) {
+ return {};
+ }
+ size_t diff_index = 0;
+ for (; diff_index < std::min(expected.size(), result.size()); ++diff_index) {
+ if (expected[diff_index] != result[diff_index]) {
+ break;
+ }
+ }
+
+ if (diff_index < 10) {
+ auto expected_short = MakePrintable(expected);
+ auto result_short = MakePrintable(result);
+ return StringPrintf("msg: expected '%s' vs '%s'", expected_short.c_str(),
+ result_short.c_str());
+ }
+
+ auto expected_short = MakePrintable(expected.substr(diff_index));
+ auto result_short = MakePrintable(result.substr(diff_index));
+ return StringPrintf("msg: index %zu: expected '%s' vs '%s'", diff_index, expected_short.c_str(),
+ result_short.c_str());
+}
+
+std::string CompareRegexMessages(const std::string& expected, const std::string& result) {
+ auto expected_pieces = Split(expected, std::string("\0", 1));
+ auto result_pieces = Split(result, std::string("\0", 1));
+
+ if (expected_pieces.size() != 3 || result_pieces.size() != 3) {
+ return StringPrintf(
+ "msg: should have 3 null delimited strings found %d in expected, %d in result: "
+ "'%s' vs '%s'",
+ static_cast<int>(expected_pieces.size()), static_cast<int>(result_pieces.size()),
+ MakePrintable(expected).c_str(), MakePrintable(result).c_str());
+ }
+ if (expected_pieces[0] != result_pieces[0]) {
+ return StringPrintf("msg: tag/priority mismatch expected '%s' vs '%s'",
+ MakePrintable(expected_pieces[0]).c_str(),
+ MakePrintable(result_pieces[0]).c_str());
+ }
+ std::regex expected_tag_regex(expected_pieces[1]);
+ if (!std::regex_search(result_pieces[1], expected_tag_regex)) {
+ return StringPrintf("msg: message regex mismatch expected '%s' vs '%s'",
+ MakePrintable(expected_pieces[1]).c_str(),
+ MakePrintable(result_pieces[1]).c_str());
+ }
+ if (expected_pieces[2] != result_pieces[2]) {
+ return StringPrintf("msg: nothing expected after final null character '%s' vs '%s'",
+ MakePrintable(expected_pieces[2]).c_str(),
+ MakePrintable(result_pieces[2]).c_str());
+ }
+ return {};
+}
+
+void CompareLogMessages(const std::vector<LogMessage>& expected,
+ const std::vector<LogMessage>& result) {
+ EXPECT_EQ(expected.size(), result.size());
+ size_t end = std::min(expected.size(), result.size());
+ size_t num_errors = 0;
+ for (size_t i = 0; i < end; ++i) {
+ auto errors =
+ CompareLoggerEntries(expected[i].entry, result[i].entry, expected[i].regex_compare);
+ auto msg_error = expected[i].regex_compare
+ ? CompareRegexMessages(expected[i].message, result[i].message)
+ : CompareMessages(expected[i].message, result[i].message);
+ if (!msg_error.empty()) {
+ errors.emplace_back(msg_error);
+ }
+ if (!errors.empty()) {
+ GTEST_LOG_(ERROR) << "Mismatch log message " << i << "\n" << Join(errors, "\n");
+ ++num_errors;
+ }
+ }
+ EXPECT_EQ(0U, num_errors);
+}
+
class TestWriter : public LogWriter {
public:
- TestWriter(std::vector<std::pair<logger_entry, std::string>>* msgs, bool* released)
+ TestWriter(std::vector<LogMessage>* msgs, bool* released)
: LogWriter(0, true, true), msgs_(msgs), released_(released) {}
bool Write(const logger_entry& entry, const char* message) override {
- msgs_->emplace_back(entry, std::string(message, entry.len));
+ msgs_->emplace_back(LogMessage{entry, std::string(message, entry.len), false});
return true;
}
@@ -74,7 +213,7 @@
std::string name() const override { return "test_writer"; }
private:
- std::vector<std::pair<logger_entry, std::string>>* msgs_;
+ std::vector<LogMessage>* msgs_;
bool* released_;
};
@@ -84,107 +223,20 @@
log_buffer_.reset(new ChattyLogBuffer(&reader_list_, &tags_, &prune_, &stats_));
}
- void FixupMessages(std::vector<std::pair<logger_entry, std::string>>* messages) {
- for (auto& [entry, message] : *messages) {
+ void FixupMessages(std::vector<LogMessage>* messages) {
+ for (auto& [entry, message, _] : *messages) {
entry.hdr_size = sizeof(logger_entry);
entry.len = message.size();
}
}
- void LogMessages(const std::vector<std::pair<logger_entry, std::string>>& messages) {
- for (auto& [entry, message] : messages) {
+ void LogMessages(const std::vector<LogMessage>& messages) {
+ for (auto& [entry, message, _] : messages) {
log_buffer_->Log(static_cast<log_id_t>(entry.lid), log_time(entry.sec, entry.nsec),
entry.uid, entry.pid, entry.tid, message.c_str(), message.size());
}
}
- std::vector<std::string> CompareLoggerEntries(const logger_entry& expected,
- const logger_entry& result) {
- std::vector<std::string> errors;
- if (expected.len != result.len) {
- errors.emplace_back(
- StringPrintf("len: %" PRIu16 " vs %" PRIu16, expected.len, result.len));
- }
- if (expected.hdr_size != result.hdr_size) {
- errors.emplace_back(StringPrintf("hdr_size: %" PRIu16 " vs %" PRIu16, expected.hdr_size,
- result.hdr_size));
- }
- if (expected.pid != result.pid) {
- errors.emplace_back(
- StringPrintf("pid: %" PRIi32 " vs %" PRIi32, expected.pid, result.pid));
- }
- if (expected.tid != result.tid) {
- errors.emplace_back(
- StringPrintf("tid: %" PRIu32 " vs %" PRIu32, expected.tid, result.tid));
- }
- if (expected.sec != result.sec) {
- errors.emplace_back(
- StringPrintf("sec: %" PRIu32 " vs %" PRIu32, expected.sec, result.sec));
- }
- if (expected.nsec != result.nsec) {
- errors.emplace_back(
- StringPrintf("nsec: %" PRIu32 " vs %" PRIu32, expected.nsec, result.nsec));
- }
- if (expected.lid != result.lid) {
- errors.emplace_back(
- StringPrintf("lid: %" PRIu32 " vs %" PRIu32, expected.lid, result.lid));
- }
- if (expected.uid != result.uid) {
- errors.emplace_back(
- StringPrintf("uid: %" PRIu32 " vs %" PRIu32, expected.uid, result.uid));
- }
- return errors;
- }
-
- std::string CompareMessages(const std::string& expected, const std::string& result) {
- if (expected == result) {
- return {};
- }
- auto shorten_string = [](const std::string& in) {
- if (in.size() > 10) {
- return in.substr(0, 10) + "...";
- }
- return in;
- };
-
- size_t diff_index = 0;
- for (; diff_index < std::min(expected.size(), result.size()); ++diff_index) {
- if (expected[diff_index] != result[diff_index]) {
- break;
- }
- }
-
- if (diff_index < 10) {
- auto expected_short = shorten_string(expected);
- auto result_short = shorten_string(result);
- return StringPrintf("msg: %s vs %s", expected_short.c_str(), result_short.c_str());
- }
-
- auto expected_short = shorten_string(expected.substr(diff_index));
- auto result_short = shorten_string(result.substr(diff_index));
- return StringPrintf("msg: index %zu: %s vs %s", diff_index, expected_short.c_str(),
- result_short.c_str());
- }
-
- void CompareLogMessages(const std::vector<std::pair<logger_entry, std::string>>& expected,
- const std::vector<std::pair<logger_entry, std::string>>& result) {
- EXPECT_EQ(expected.size(), result.size());
- size_t end = std::min(expected.size(), result.size());
- size_t num_errors = 0;
- for (size_t i = 0; i < end; ++i) {
- auto errors = CompareLoggerEntries(expected[i].first, result[i].first);
- auto msg_error = CompareMessages(expected[i].second, result[i].second);
- if (!msg_error.empty()) {
- errors.emplace_back(msg_error);
- }
- if (!errors.empty()) {
- GTEST_LOG_(ERROR) << "Mismatch log message " << i << " " << Join(errors, " ");
- ++num_errors;
- }
- }
- EXPECT_EQ(0U, num_errors);
- }
-
LogReaderList reader_list_;
LogTags tags_;
PruneList prune_;
@@ -193,7 +245,7 @@
};
TEST_F(LogBufferTest, smoke) {
- std::vector<std::pair<logger_entry, std::string>> log_messages = {
+ std::vector<LogMessage> log_messages = {
{{
.pid = 1,
.tid = 1,
@@ -207,7 +259,7 @@
FixupMessages(&log_messages);
LogMessages(log_messages);
- std::vector<std::pair<logger_entry, std::string>> read_log_messages;
+ std::vector<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
uint64_t flush_result = log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
EXPECT_EQ(1ULL, flush_result);
@@ -215,7 +267,7 @@
}
TEST_F(LogBufferTest, smoke_with_reader_thread) {
- std::vector<std::pair<logger_entry, std::string>> log_messages = {
+ std::vector<LogMessage> log_messages = {
{{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
"first"},
{{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
@@ -240,7 +292,7 @@
FixupMessages(&log_messages);
LogMessages(log_messages);
- std::vector<std::pair<logger_entry, std::string>> read_log_messages;
+ std::vector<LogMessage> read_log_messages;
bool released = false;
{
@@ -264,7 +316,7 @@
// Generate random messages, set the 'sec' parameter explicit though, to be able to track the
// expected order of messages.
-std::pair<logger_entry, std::string> GenerateRandomLogMessage(uint32_t sec) {
+LogMessage GenerateRandomLogMessage(uint32_t sec) {
auto rand_uint32 = [](int max) -> uint32_t { return rand() % max; };
logger_entry entry = {
.hdr_size = sizeof(logger_entry),
@@ -308,13 +360,13 @@
TEST_F(LogBufferTest, random_messages) {
srand(1);
- std::vector<std::pair<logger_entry, std::string>> log_messages;
+ std::vector<LogMessage> log_messages;
for (size_t i = 0; i < 1000; ++i) {
log_messages.emplace_back(GenerateRandomLogMessage(i));
}
LogMessages(log_messages);
- std::vector<std::pair<logger_entry, std::string>> read_log_messages;
+ std::vector<LogMessage> read_log_messages;
bool released = false;
{
@@ -335,3 +387,184 @@
}
CompareLogMessages(log_messages, read_log_messages);
}
+
+TEST_F(LogBufferTest, deduplication_simple) {
+ auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
+ bool regex = false) -> LogMessage {
+ logger_entry entry = {
+ .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
+ std::string message;
+ message.push_back(ANDROID_LOG_INFO);
+ message.append(tag);
+ message.push_back('\0');
+ message.append(msg);
+ message.push_back('\0');
+ return {entry, message, regex};
+ };
+
+ // clang-format off
+ std::vector<LogMessage> log_messages = {
+ make_message(0, "test_tag", "duplicate"),
+ make_message(1, "test_tag", "duplicate"),
+ make_message(2, "test_tag", "not_same"),
+ make_message(3, "test_tag", "duplicate"),
+ make_message(4, "test_tag", "duplicate"),
+ make_message(5, "test_tag", "not_same"),
+ make_message(6, "test_tag", "duplicate"),
+ make_message(7, "test_tag", "duplicate"),
+ make_message(8, "test_tag", "duplicate"),
+ make_message(9, "test_tag", "not_same"),
+ make_message(10, "test_tag", "duplicate"),
+ make_message(11, "test_tag", "duplicate"),
+ make_message(12, "test_tag", "duplicate"),
+ make_message(13, "test_tag", "duplicate"),
+ make_message(14, "test_tag", "duplicate"),
+ make_message(15, "test_tag", "duplicate"),
+ make_message(16, "test_tag", "not_same"),
+ make_message(100, "test_tag", "duplicate"),
+ make_message(200, "test_tag", "duplicate"),
+ make_message(300, "test_tag", "duplicate"),
+ };
+ // clang-format on
+ FixupMessages(&log_messages);
+ LogMessages(log_messages);
+
+ std::vector<LogMessage> read_log_messages;
+ std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
+ log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
+
+ std::vector<LogMessage> expected_log_messages = {
+ make_message(0, "test_tag", "duplicate"),
+ make_message(1, "test_tag", "duplicate"),
+ make_message(2, "test_tag", "not_same"),
+ make_message(3, "test_tag", "duplicate"),
+ make_message(4, "test_tag", "duplicate"),
+ make_message(5, "test_tag", "not_same"),
+ // 3 duplicate logs together print the first, a 1 count chatty message, then the last.
+ make_message(6, "test_tag", "duplicate"),
+ make_message(7, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ expire 1 line", true),
+ make_message(8, "test_tag", "duplicate"),
+ make_message(9, "test_tag", "not_same"),
+ // 6 duplicate logs together print the first, a 4 count chatty message, then the last.
+ make_message(10, "test_tag", "duplicate"),
+ make_message(14, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ expire 4 lines", true),
+ make_message(15, "test_tag", "duplicate"),
+ make_message(16, "test_tag", "not_same"),
+ // duplicate logs > 1 minute apart are not deduplicated.
+ make_message(100, "test_tag", "duplicate"),
+ make_message(200, "test_tag", "duplicate"),
+ make_message(300, "test_tag", "duplicate"),
+ };
+ FixupMessages(&expected_log_messages);
+ CompareLogMessages(expected_log_messages, read_log_messages);
+};
+
+TEST_F(LogBufferTest, deduplication_overflow) {
+ auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
+ bool regex = false) -> LogMessage {
+ logger_entry entry = {
+ .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
+ std::string message;
+ message.push_back(ANDROID_LOG_INFO);
+ message.append(tag);
+ message.push_back('\0');
+ message.append(msg);
+ message.push_back('\0');
+ return {entry, message, regex};
+ };
+
+ uint32_t sec = 0;
+ std::vector<LogMessage> log_messages = {
+ make_message(sec++, "test_tag", "normal"),
+ };
+ size_t expired_per_chatty_message = std::numeric_limits<uint16_t>::max();
+ for (size_t i = 0; i < expired_per_chatty_message + 3; ++i) {
+ log_messages.emplace_back(make_message(sec++, "test_tag", "duplicate"));
+ }
+ log_messages.emplace_back(make_message(sec++, "test_tag", "normal"));
+ FixupMessages(&log_messages);
+ LogMessages(log_messages);
+
+ std::vector<LogMessage> read_log_messages;
+ std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
+ log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
+
+ std::vector<LogMessage> expected_log_messages = {
+ make_message(0, "test_tag", "normal"),
+ make_message(1, "test_tag", "duplicate"),
+ make_message(expired_per_chatty_message + 1, "chatty",
+ "uid=0\\([^\\)]+\\) [^ ]+ expire 65535 lines", true),
+ make_message(expired_per_chatty_message + 2, "chatty",
+ "uid=0\\([^\\)]+\\) [^ ]+ expire 1 line", true),
+ make_message(expired_per_chatty_message + 3, "test_tag", "duplicate"),
+ make_message(expired_per_chatty_message + 4, "test_tag", "normal"),
+ };
+ FixupMessages(&expected_log_messages);
+ CompareLogMessages(expected_log_messages, read_log_messages);
+}
+
+TEST_F(LogBufferTest, deduplication_liblog) {
+ auto make_message = [&](uint32_t sec, int32_t tag, int32_t count) -> LogMessage {
+ logger_entry entry = {
+ .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_EVENTS, .uid = 0};
+ android_log_event_int_t liblog_event = {
+ .header.tag = tag, .payload.type = EVENT_TYPE_INT, .payload.data = count};
+ return {entry, std::string(reinterpret_cast<char*>(&liblog_event), sizeof(liblog_event)),
+ false};
+ };
+
+ // LIBLOG_LOG_TAG
+ std::vector<LogMessage> log_messages = {
+ make_message(0, 1234, 1),
+ make_message(1, LIBLOG_LOG_TAG, 3),
+ make_message(2, 1234, 2),
+ make_message(3, LIBLOG_LOG_TAG, 3),
+ make_message(4, LIBLOG_LOG_TAG, 4),
+ make_message(5, 1234, 223),
+ make_message(6, LIBLOG_LOG_TAG, 2),
+ make_message(7, LIBLOG_LOG_TAG, 3),
+ make_message(8, LIBLOG_LOG_TAG, 4),
+ make_message(9, 1234, 227),
+ make_message(10, LIBLOG_LOG_TAG, 1),
+ make_message(11, LIBLOG_LOG_TAG, 3),
+ make_message(12, LIBLOG_LOG_TAG, 2),
+ make_message(13, LIBLOG_LOG_TAG, 3),
+ make_message(14, LIBLOG_LOG_TAG, 5),
+ make_message(15, 1234, 227),
+ make_message(16, LIBLOG_LOG_TAG, 2),
+ make_message(17, LIBLOG_LOG_TAG, std::numeric_limits<int32_t>::max()),
+ make_message(18, LIBLOG_LOG_TAG, 3),
+ make_message(19, LIBLOG_LOG_TAG, 5),
+ make_message(20, 1234, 227),
+ };
+ FixupMessages(&log_messages);
+ LogMessages(log_messages);
+
+ std::vector<LogMessage> read_log_messages;
+ std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
+ log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
+
+ std::vector<LogMessage> expected_log_messages = {
+ make_message(0, 1234, 1),
+ make_message(1, LIBLOG_LOG_TAG, 3),
+ make_message(2, 1234, 2),
+ make_message(3, LIBLOG_LOG_TAG, 3),
+ make_message(4, LIBLOG_LOG_TAG, 4),
+ make_message(5, 1234, 223),
+ // More than 2 liblog events (3 here), sum their value into the third message.
+ make_message(6, LIBLOG_LOG_TAG, 2),
+ make_message(8, LIBLOG_LOG_TAG, 7),
+ make_message(9, 1234, 227),
+ // More than 2 liblog events (5 here), sum their value into the third message.
+ make_message(10, LIBLOG_LOG_TAG, 1),
+ make_message(14, LIBLOG_LOG_TAG, 13),
+ make_message(15, 1234, 227),
+ // int32_t max is the max for a chatty message, beyond that we must use new messages.
+ make_message(16, LIBLOG_LOG_TAG, 2),
+ make_message(17, LIBLOG_LOG_TAG, std::numeric_limits<int32_t>::max()),
+ make_message(19, LIBLOG_LOG_TAG, 8),
+ make_message(20, 1234, 227),
+ };
+ FixupMessages(&expected_log_messages);
+ CompareLogMessages(expected_log_messages, read_log_messages);
+};
\ No newline at end of file
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 14bcb63..bb7621d 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -79,12 +79,9 @@
}
}
-void LogStatistics::AddTotal(LogBufferElement* element) {
+void LogStatistics::AddTotal(log_id_t log_id, uint16_t size) {
auto lock = std::lock_guard{lock_};
- if (element->getDropped()) return;
- log_id_t log_id = element->getLogId();
- uint16_t size = element->getMsgLen();
mSizesTotal[log_id] += size;
SizesTotal += size;
++mElementsTotal[log_id];
diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h
index 53c9bb6..7d13ff7 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -666,7 +666,7 @@
public:
LogStatistics(bool enable_statistics);
- void AddTotal(LogBufferElement* entry) EXCLUDES(lock_);
+ void AddTotal(log_id_t log_id, uint16_t size) EXCLUDES(lock_);
void Add(LogBufferElement* entry) EXCLUDES(lock_);
void Subtract(LogBufferElement* entry) EXCLUDES(lock_);
// entry->setDropped(1) must follow this call
diff --git a/logd/rwlock.h b/logd/rwlock.h
new file mode 100644
index 0000000..2b27ff1
--- /dev/null
+++ b/logd/rwlock.h
@@ -0,0 +1,56 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#pragma once
+
+#include <pthread.h>
+
+#include <android-base/macros.h>
+#include <android-base/thread_annotations.h>
+
+// As of the end of May 2020, std::shared_mutex is *not* simply a pthread_rwlock, but rather a
+// combination of std::mutex and std::condition variable, which is obviously less efficient. This
+// immitates what std::shared_mutex should be doing and is compatible with RAII thread wrappers.
+
+class SHARED_CAPABILITY("mutex") RwLock {
+ public:
+ RwLock() {}
+ ~RwLock() {}
+
+ void lock() ACQUIRE() { pthread_rwlock_wrlock(&rwlock_); }
+ void lock_shared() ACQUIRE_SHARED() { pthread_rwlock_rdlock(&rwlock_); }
+
+ void unlock() RELEASE() { pthread_rwlock_unlock(&rwlock_); }
+
+ private:
+ pthread_rwlock_t rwlock_ = PTHREAD_RWLOCK_INITIALIZER;
+};
+
+// std::shared_lock does not have thread annotations, so we need our own.
+
+class SCOPED_CAPABILITY SharedLock {
+ public:
+ SharedLock(RwLock& lock) ACQUIRE_SHARED(lock) : lock_(lock) { lock_.lock_shared(); }
+ ~SharedLock() RELEASE() { lock_.unlock(); }
+
+ void lock_shared() ACQUIRE_SHARED() { lock_.lock_shared(); }
+ void unlock() RELEASE() { lock_.unlock(); }
+
+ DISALLOW_IMPLICIT_CONSTRUCTORS(SharedLock);
+
+ private:
+ RwLock& lock_;
+};