From 09d663229fe253ec91b341c9f15ed7f2d22f931a Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 14 Mar 2017 13:11:12 -0700 Subject: [PATCH 1/2] logd: cap how far back in-place sort will go to 5 seconds Add some deterministic behavior should the user change the hour backwards when altering the device time, prevent sort-in-place and cause the logger to land the new entries at the end. Do not limit how far kernel logs can be sorted. Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests Bug: 35373582 Change-Id: Ie897c40b97adf1e3996687a0e28c1199c41e0d0c --- logd/LogBuffer.cpp | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 1b79e89b9..352fc187f 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -370,13 +370,19 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, // assumes mLogElementsLock held, owns elem, will look after garbage collection void LogBuffer::log(LogBufferElement* elem) { + // cap on how far back we will sort in-place, otherwise append + static uint32_t too_far_back = 5; // five seconds // 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; if (__predict_true(it != mLogElements.begin())) --it; if (__predict_false(it == mLogElements.begin()) || - __predict_true((*it)->getRealTime() <= elem->getRealTime())) { + __predict_true((*it)->getRealTime() <= elem->getRealTime()) || + __predict_false((((*it)->getRealTime().tv_sec - too_far_back) > + elem->getRealTime().tv_sec) && + (elem->getLogId() != LOG_ID_KERNEL) && + ((*it)->getLogId() != LOG_ID_KERNEL))) { mLogElements.push_back(elem); } else { log_time end = log_time::EPOCH; From 5e001776f405098cc825c9f6de546cd5b92b70e4 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 14 Mar 2017 13:23:06 -0700 Subject: [PATCH 2/2] logd: wakeup wrap timeout if realtime changes drastically --wrap flag in logcat translates directly to the mTimeout inside logd, the value set is ANDROID_LOG_WRAP_DEFAULT_TIMEOUT defined in as 7200 or 2 hours. For a non blocking read with a selected timeout, the logger waits until either the log buffer is about to 'wrap' and prune the log entry, or at the specified timeout. Non blocking in the logger context means that when there are no more log entries, the socket is closed. clock_gettime(CLOCK_REALTIME) is UTC 1970 epoch *NIX time. Is only affected for time updates, not timezone or daylight savings time. If there is a large user initiated time change, both the log entries and the timeout mentioned above really get called into question, so we trigger a release of the logs for clarity. This is so that the log reader can handle the disruptively updated time, and can immediately check the local time if necessary. The logger has a 5 second window for entries to land in time sorted order into the logging list. This should offer the log reader some differentiation between logging order sequence for monotonically increasing time, and sequence order in the face of user initiated time adjustments that break monotonicity. This change is about major time adjustments that can cause Fear, Uncertainty or Doubt about log entries. By returning, immediate action can be taken, rather than having to comb through the logs with less details about the time disruptions in hand. The least it can do is record what we have, and restart the call with a new tail time and timeout. Test: gTest liblog-unit-tests logcat-unit-test logd-unit-tests Bug: 35373582 Change-Id: I92cac83be99d68634ffd4ebd2f3a3067cfd0e942 --- logd/FlushCommand.cpp | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp index ff6bff8eb..c67d2bfb1 100644 --- a/logd/FlushCommand.cpp +++ b/logd/FlushCommand.cpp @@ -57,8 +57,18 @@ void FlushCommand::runSocketCommand(SocketClient* client) { entry = (*it); if (entry->mClient == client) { if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) { - LogTimeEntry::unlock(); - return; + if (mReader.logbuf().isMonotonic()) { + LogTimeEntry::unlock(); + return; + } + // If the user changes the time in a gross manner that + // invalidates the timeout, fall through and trigger. + log_time now(CLOCK_REALTIME); + if (((entry->mEnd + entry->mTimeout) > now) && + (now > entry->mEnd)) { + LogTimeEntry::unlock(); + return; + } } entry->triggerReader_Locked(); if (entry->runningReader_Locked()) {