From 5836379b2114f47c53485b42ab157104c29b2c4e Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 17 Apr 2017 12:46:12 -0700 Subject: [PATCH 1/4] logd: regression in handling watermark boundary. Deal with a regression introduced in commit 5a34d6ea43d28f3b5d27bf6dd5b9fa31ec033531 (logd: drop mSequence from LogBufferElement) where log_time was compared against nsec() time miscalculating the watermark boundary. When dealing with logcat -t/-T, or any tail reading, add a margin to prune to back off by a period of 3 seconds (pruneMargin). Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests Bug: 37378309 Change-Id: I72ea858e4e7b5fa91741ea84c40d2e7c3c4aa031 --- logd/LogBuffer.cpp | 18 ++++++++++++------ logd/LogBuffer.h | 1 + 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 0c7019ad8..4a790c9f5 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -43,6 +43,8 @@ // Default #define log_buffer_size(id) mMaxSize[id] +const log_time LogBuffer::pruneMargin(3, 0); + void LogBuffer::init() { log_id_for_each(i) { mLastSet[i] = false; @@ -672,6 +674,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } times++; } + log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max); + if (oldest) watermark = oldest->mStart - pruneMargin; LogBufferElementCollection::iterator it; @@ -693,7 +697,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { oldest->triggerReader_Locked(); @@ -785,7 +789,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { while (it != mLogElements.end()) { LogBufferElement* element = *it; - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { oldest->triggerReader_Locked(); @@ -939,7 +943,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (whitelist) { break; @@ -983,7 +987,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island @@ -1090,13 +1094,15 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, // client wants to start from the beginning it = mLogElements.begin(); } else { - LogBufferElementCollection::iterator last; // 3 second limit to continue search for out-of-order entries. - log_time min = start - log_time(3, 0); + log_time min = start - pruneMargin; + // Cap to 300 iterations we look back for out-of-order entries. size_t count = 300; + // Client wants to start from some specified time. Chances are // we are better off starting from the end of the time sorted list. + LogBufferElementCollection::iterator last; for (last = it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { --it; diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 19d11cb7f..1272c20f6 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -174,6 +174,7 @@ class LogBuffer { private: static constexpr size_t minPrune = 4; static constexpr size_t maxPrune = 256; + static const log_time pruneMargin; void maybePrune(log_id_t id); bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT); From 3614a0c5d4aec84fbc5f6cbf1e919e8b3825b818 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 17 Apr 2017 12:46:12 -0700 Subject: [PATCH 2/4] logd: iterator corruption paranoia Add checking for impossible(tm) scenarios within LogBuffer::flushTo: 1) When iterating through the log entries, check if the iterator returns two identical element references and break out of the loop. 2) Cap the maximum number of log entries we will skip while holding the iterator lock at 4194304, break out of the loop. We print a message to the kernel logs if we hit these cases. ToDo: Remove this paranoia at some future date. Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests Bug: 37378309 Change-Id: I789594649db14093238828b9f6d1daeca8b780c2 --- logd/LogBuffer.cpp | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 4a790c9f5..a6bea0cdf 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -1118,9 +1118,22 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, log_time max = start; + LogBufferElement* lastElement = nullptr; // iterator corruption paranoia + static const size_t maxSkip = 4194304; // maximum entries to skip + size_t skip = maxSkip; for (; it != mLogElements.end(); ++it) { LogBufferElement* element = *it; + if (!--skip) { + android::prdebug("reader.per: too many elements skipped"); + break; + } + if (element == lastElement) { + android::prdebug("reader.per: identical elements"); + break; + } + lastElement = element; + if (!privileged && (element->getUid() != uid)) { continue; } @@ -1165,6 +1178,7 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, return max; } + skip = maxSkip; pthread_mutex_lock(&mLogElementsLock); } pthread_mutex_unlock(&mLogElementsLock); From d87d47f7dda69bf5729c31fb832e6e42886e68c8 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 17 Apr 2017 12:37:11 -0700 Subject: [PATCH 3/4] liblog: log_time add explicit to some constructors. Add explicit to constructors, to prevent implicit conversions. Test: compile Bug: 37378309 Change-Id: I3f9f8d561e84c492eafa6528db7c238da072dad8 --- liblog/include/log/log_time.h | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/liblog/include/log/log_time.h b/liblog/include/log/log_time.h index 5f70f7d4c..9ece0b328 100644 --- a/liblog/include/log/log_time.h +++ b/liblog/include/log/log_time.h @@ -41,13 +41,12 @@ struct log_time { static const uint32_t tv_sec_max = 0xFFFFFFFFUL; static const uint32_t tv_nsec_max = 999999999UL; - log_time(const timespec& T) { - tv_sec = static_cast(T.tv_sec); - tv_nsec = static_cast(T.tv_nsec); + log_time(const timespec& T) + : tv_sec(static_cast(T.tv_sec)), + tv_nsec(static_cast(T.tv_nsec)) { } - log_time(uint32_t sec, uint32_t nsec) { - tv_sec = sec; - tv_nsec = nsec; + explicit log_time(uint32_t sec, uint32_t nsec = 0) + : tv_sec(sec), tv_nsec(nsec) { } #ifdef _SYSTEM_CORE_INCLUDE_PRIVATE_ANDROID_LOGGER_H_ #define __struct_log_time_private_defined @@ -56,14 +55,14 @@ struct log_time { log_time() { } #ifdef __linux__ - log_time(clockid_t id) { + explicit log_time(clockid_t id) { timespec T; clock_gettime(id, &T); tv_sec = static_cast(T.tv_sec); tv_nsec = static_cast(T.tv_nsec); } #endif - log_time(const char* T) { + explicit log_time(const char* T) { const uint8_t* c = reinterpret_cast(T); tv_sec = c[0] | (static_cast(c[1]) << 8) | (static_cast(c[2]) << 16) | From 24aa9a41e158e197ff8c22c731a9208d650a0a38 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 17 Apr 2017 12:39:13 -0700 Subject: [PATCH 4/4] logd: instrument tests better for failure Failure to open socket misbehaved and told us nothing. Test: gTest logd-unit-tests Bug: 37378309 Change-Id: Iec369a50ccb1027e96947465e90d9572c9f4047f --- logd/tests/logd_test.cpp | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index 88cb67a96..a1d154ae7 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -670,8 +670,12 @@ TEST(logd, timeout) { while (--i) { int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET); - EXPECT_LT(0, fd); - if (fd < 0) _exit(fd); + int save_errno = errno; + if (fd < 0) { + fprintf(stderr, "failed to open /dev/socket/logdr %s\n", + strerror(save_errno)); + _exit(fd); + } std::string ask = android::base::StringPrintf( "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32 @@ -723,8 +727,12 @@ TEST(logd, timeout) { // active _or_ inactive during the test. if (content_timeout) { log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); - EXPECT_FALSE(msg < now); - if (msg < now) _exit(-1); + if (msg < now) { + fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec, + msg_timeout.entry.nsec, (unsigned)now.tv_sec, + (unsigned)now.tv_nsec); + _exit(-1); + } if (msg > now) { now = msg; now.tv_sec += 30;