From b75cce0389748bea111ca62af623645117e12d9d Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 30 Nov 2015 11:35:56 -0800 Subject: [PATCH 1/6] logd: wakeup on wrap or timeout If a timeout is specified for the reader, then go to sleep with the socket open. If the start time is about to get pruned in the specified log buffers, then wakeup and dump the logs; or wakeup on timeout, whichever comes first. Bug: 25929746 Change-Id: I7d2421c2c5083b33747b84f74d9a560d3ba645df --- logd/FlushCommand.cpp | 13 ++++-- logd/FlushCommand.h | 4 +- logd/LogBuffer.cpp | 94 ++++++++++++++++++++++++++++--------------- logd/LogReader.cpp | 10 ++++- logd/LogTimes.cpp | 22 +++++++++- logd/LogTimes.h | 3 +- 6 files changed, 106 insertions(+), 40 deletions(-) diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp index 823a842fb..bf650cdaa 100644 --- a/logd/FlushCommand.cpp +++ b/logd/FlushCommand.cpp @@ -27,13 +27,15 @@ FlushCommand::FlushCommand(LogReader &reader, unsigned long tail, unsigned int logMask, pid_t pid, - uint64_t start) : + uint64_t start, + uint64_t timeout) : mReader(reader), mNonBlock(nonBlock), mTail(tail), mLogMask(logMask), mPid(pid), - mStart(start) { + mStart(start), + mTimeout(timeout) { } // runSocketCommand is called once for every open client on the @@ -54,6 +56,10 @@ void FlushCommand::runSocketCommand(SocketClient *client) { while(it != times.end()) { entry = (*it); if (entry->mClient == client) { + if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) { + LogTimeEntry::unlock(); + return; + } entry->triggerReader_Locked(); if (entry->runningReader_Locked()) { LogTimeEntry::unlock(); @@ -71,7 +77,8 @@ void FlushCommand::runSocketCommand(SocketClient *client) { LogTimeEntry::unlock(); return; } - entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, mPid, mStart); + entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, + mPid, mStart, mTimeout); times.push_front(entry); } diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h index 61c6858c2..e0f2212be 100644 --- a/logd/FlushCommand.h +++ b/logd/FlushCommand.h @@ -32,6 +32,7 @@ class FlushCommand : public SocketClientCommand { unsigned int mLogMask; pid_t mPid; uint64_t mStart; + uint64_t mTimeout; public: FlushCommand(LogReader &mReader, @@ -39,7 +40,8 @@ public: unsigned long tail = -1, unsigned int logMask = -1, pid_t pid = 0, - uint64_t start = 1); + uint64_t start = 1, + uint64_t timeout = 0); virtual void runSocketCommand(SocketClient *client); static bool hasReadLogs(SocketClient *client); diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index c8127c3ac..6770bb7f2 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -129,41 +129,57 @@ void LogBuffer::init() { } bool lastMonotonic = monotonic; monotonic = android_log_clockid() == CLOCK_MONOTONIC; - if (lastMonotonic == monotonic) { - return; + if (lastMonotonic != monotonic) { + // + // Fixup all timestamps, may not be 100% accurate, but better than + // throwing what we have away when we get 'surprised' by a change. + // In-place element fixup so no need to check reader-lock. Entries + // should already be in timestamp order, but we could end up with a + // few out-of-order entries if new monotonics come in before we + // are notified of the reinit change in status. A Typical example would + // be: + // --------- beginning of system + // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data + // --------- beginning of kernel + // 0.000000 0 0 I : Initializing cgroup subsys + // as the act of mounting /data would trigger persist.logd.timestamp to + // be corrected. 1/30 corner case YMMV. + // + pthread_mutex_lock(&mLogElementsLock); + LogBufferElementCollection::iterator it = mLogElements.begin(); + while((it != mLogElements.end())) { + LogBufferElement *e = *it; + if (monotonic) { + if (!android::isMonotonic(e->mRealTime)) { + LogKlog::convertRealToMonotonic(e->mRealTime); + } + } else { + if (android::isMonotonic(e->mRealTime)) { + LogKlog::convertMonotonicToReal(e->mRealTime); + } + } + ++it; + } + pthread_mutex_unlock(&mLogElementsLock); } + // We may have been triggered by a SIGHUP. Release any sleeping reader + // threads to dump their current content. // - // Fixup all timestamps, may not be 100% accurate, but better than - // throwing what we have away when we get 'surprised' by a change. - // In-place element fixup so no need to check reader-lock. Entries - // should already be in timestamp order, but we could end up with a - // few out-of-order entries if new monotonics come in before we - // are notified of the reinit change in status. A Typical example would - // be: - // --------- beginning of system - // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data - // --------- beginning of kernel - // 0.000000 0 0 I : Initializing cgroup subsys cpuacct - // as the act of mounting /data would trigger persist.logd.timestamp to - // be corrected. 1/30 corner case YMMV. - // - pthread_mutex_lock(&mLogElementsLock); - LogBufferElementCollection::iterator it = mLogElements.begin(); - while((it != mLogElements.end())) { - LogBufferElement *e = *it; - if (monotonic) { - if (!android::isMonotonic(e->mRealTime)) { - LogKlog::convertRealToMonotonic(e->mRealTime); - } - } else { - if (android::isMonotonic(e->mRealTime)) { - LogKlog::convertMonotonicToReal(e->mRealTime); - } + // NB: this is _not_ performed in the context of a SIGHUP, it is + // performed during startup, and in context of reinit administrative thread + LogTimeEntry::lock(); + + LastLogTimes::iterator times = mTimes.begin(); + while(times != mTimes.end()) { + LogTimeEntry *entry = (*times); + if (entry->owned_Locked()) { + entry->triggerReader_Locked(); } - ++it; + times++; } - pthread_mutex_unlock(&mLogElementsLock); + + LogTimeEntry::unlock(); } LogBuffer::LogBuffer(LastLogTimes *times): @@ -429,7 +445,10 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { while(t != mTimes.end()) { LogTimeEntry *entry = (*t); if (entry->owned_Locked() && entry->isWatching(id) - && (!oldest || (oldest->mStart > entry->mStart))) { + && (!oldest || + (oldest->mStart > entry->mStart) || + ((oldest->mStart == entry->mStart) && + (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) { oldest = entry; } t++; @@ -448,8 +467,12 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } if (oldest && (oldest->mStart <= e->getSequence())) { - oldest->triggerSkip_Locked(id, pruneRows); busy = true; + if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { + oldest->triggerReader_Locked(); + } else { + oldest->triggerSkip_Locked(id, pruneRows); + } break; } @@ -523,6 +546,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { if (oldest && (oldest->mStart <= e->getSequence())) { busy = true; + if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { + oldest->triggerReader_Locked(); + } break; } @@ -648,6 +674,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island oldest->release_Locked(); + } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { + oldest->triggerReader_Locked(); } else { oldest->triggerSkip_Locked(id, pruneRows); } @@ -680,6 +708,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island oldest->release_Locked(); + } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { + oldest->triggerReader_Locked(); } else { oldest->triggerSkip_Locked(id, pruneRows); } diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 06135ddc0..c2d65b601 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -67,6 +67,14 @@ bool LogReader::onDataAvailable(SocketClient *cli) { start.strptime(cp + sizeof(_start) - 1, "%s.%q"); } + uint64_t timeout = 0; + static const char _timeout[] = " timeout="; + cp = strstr(buffer, _timeout); + if (cp) { + timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC + + log_time(CLOCK_REALTIME).nsec(); + } + unsigned int logMask = -1; static const char _logIds[] = " lids="; cp = strstr(buffer, _logIds); @@ -166,7 +174,7 @@ bool LogReader::onDataAvailable(SocketClient *cli) { } } - FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence); + FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence, timeout); command.runSocketCommand(cli); return true; } diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index 229be3cd5..b4c97a985 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -14,6 +14,7 @@ * limitations under the License. */ +#include #include #include "FlushCommand.h" @@ -26,7 +27,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER; LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - uint64_t start) : + uint64_t start, uint64_t timeout) : mRefCount(1), mRelease(false), mError(false), @@ -42,6 +43,8 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, mStart(start), mNonBlock(nonBlock), mEnd(LogBufferElement::getCurrentSequence()) { + mTimeout.tv_sec = timeout / NS_PER_SEC; + mTimeout.tv_nsec = timeout % NS_PER_SEC; pthread_cond_init(&threadTriggeredCondition, NULL); cleanSkip_Locked(); } @@ -131,6 +134,19 @@ void *LogTimeEntry::threadStart(void *obj) { uint64_t start = me->mStart; while (me->threadRunning && !me->isError_Locked()) { + + if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) { + if (pthread_cond_timedwait(&me->threadTriggeredCondition, + ×Lock, + &me->mTimeout) == ETIMEDOUT) { + me->mTimeout.tv_sec = 0; + me->mTimeout.tv_nsec = 0; + } + if (!me->threadRunning || me->isError_Locked()) { + break; + } + } + unlock(); if (me->mTail) { @@ -154,7 +170,9 @@ void *LogTimeEntry::threadStart(void *obj) { me->cleanSkip_Locked(); - pthread_cond_wait(&me->threadTriggeredCondition, ×Lock); + if (!me->mTimeout.tv_sec && !me->mTimeout.tv_nsec) { + pthread_cond_wait(&me->threadTriggeredCondition, ×Lock); + } } unlock(); diff --git a/logd/LogTimes.h b/logd/LogTimes.h index 39bcdd4e6..1117088e5 100644 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -50,10 +50,11 @@ class LogTimeEntry { public: LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - uint64_t start); + uint64_t start, uint64_t timeout); SocketClient *mClient; uint64_t mStart; + struct timespec mTimeout; const bool mNonBlock; const uint64_t mEnd; // only relevant if mNonBlock From fc9f5b8af440974fb390f4572fa526cc68d824db Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 1 Dec 2015 08:57:53 -0800 Subject: [PATCH 2/6] logd: test wakeup on wrap timeout Change-Id: I8dd605452f1fef7706a627eedc251e39bb2e34cc --- logd/tests/logd_test.cpp | 71 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 71 insertions(+) diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index bd59acbdc..4472c1dae 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -243,6 +243,12 @@ static void dump_log_msg(const char *prefix, case 3: fprintf(stderr, "lid=system "); break; + case 4: + fprintf(stderr, "lid=crash "); + break; + case 5: + fprintf(stderr, "lid=kernel "); + break; default: if (lid >= 0) { fprintf(stderr, "lid=%d ", lid); @@ -519,3 +525,68 @@ TEST(logd, benchmark) { // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) ASSERT_GT(totalSize, nowSpamSize * 2); } + +TEST(logd, timeout) { + log_msg msg_wrap, msg_timeout; + bool content_wrap = false, content_timeout = false, written = false; + unsigned int alarm_wrap = 0, alarm_timeout = 0; + // A few tries to get it right just in case wrap kicks in due to + // content providers being active during the test. + int i = 3; + + while (--i) { + int fd = socket_local_client("logdr", + ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_SEQPACKET); + ASSERT_LT(0, fd); + + struct sigaction ignore, old_sigaction; + memset(&ignore, 0, sizeof(ignore)); + ignore.sa_handler = caught_signal; + sigemptyset(&ignore.sa_mask); + sigaction(SIGALRM, &ignore, &old_sigaction); + unsigned int old_alarm = alarm(3); + + static const char ask[] = "dumpAndClose lids=0,1,2,3,4,5 timeout=6"; + written = write(fd, ask, sizeof(ask)) == sizeof(ask); + if (!written) { + alarm(old_alarm); + sigaction(SIGALRM, &old_sigaction, NULL); + close(fd); + continue; + } + + content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; + + alarm_wrap = alarm(5); + + content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; + + alarm_timeout = alarm((old_alarm <= 0) + ? old_alarm + : (old_alarm > (1 + 3 - alarm_wrap)) + ? old_alarm - 3 + alarm_wrap + : 2); + sigaction(SIGALRM, &old_sigaction, NULL); + + close(fd); + + if (!content_wrap && !alarm_wrap && content_timeout && !alarm_timeout) { + break; + } + } + + if (content_wrap) { + dump_log_msg("wrap", &msg_wrap, 3, -1); + } + + if (content_timeout) { + dump_log_msg("timeout", &msg_timeout, 3, -1); + } + + EXPECT_TRUE(written); + EXPECT_FALSE(content_wrap); + EXPECT_EQ(0U, alarm_wrap); + EXPECT_TRUE(content_timeout); + EXPECT_NE(0U, alarm_timeout); +} From f8e546e6090002cde90c21c83b8cdef311e50816 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 30 Nov 2015 11:36:09 -0800 Subject: [PATCH 3/6] liblog: Support for ANDROID_LOG_WRAP mode flag on reader If ANDROID_LOG_WRAP is specified, add timeout=3600 to the reader request. logd will comply by going to sleep with the socket open. If the start time is about to wrap or get pruned in the specified log buffers, then wakeup and dump the logs; or wakeup on timeout, whichever comes first. Bug: 25929746 Change-Id: I531b4317a20abcf3ba87d78c68fa2f268a4488ab --- include/log/logger.h | 2 ++ liblog/README | 4 ++++ liblog/log_read.c | 8 ++++++++ 3 files changed, 14 insertions(+) diff --git a/include/log/logger.h b/include/log/logger.h index ff70529fb..b3928a713 100644 --- a/include/log/logger.h +++ b/include/log/logger.h @@ -163,6 +163,8 @@ int android_logger_set_prune_list(struct logger_list *logger_list, #define ANDROID_LOG_RDWR O_RDWR #define ANDROID_LOG_ACCMODE O_ACCMODE #define ANDROID_LOG_NONBLOCK O_NONBLOCK +#define ANDROID_LOG_WRAP 0x40000000 /* Block until buffer about to wrap */ +#define ANDROID_LOG_WRAP_DEFAULT_TIMEOUT 7200 /* 2 hour default */ #define ANDROID_LOG_PSTORE 0x80000000 struct logger_list *android_logger_list_alloc(int mode, diff --git a/liblog/README b/liblog/README index f29ac045b..df1e68c65 100644 --- a/liblog/README +++ b/liblog/README @@ -116,6 +116,10 @@ DESCRIPTION code, otherwise the android_logger_list_read call will block for new entries. + The ANDROID_LOG_WRAP mode flag to the android_logger_list_alloc_time + signals logd to quiesce the reader until the buffer is about to prune + at the start time then proceed to dumping content. + The ANDROID_LOG_PSTORE mode flag to the android_logger_open is used to switch from the active logs to the persistent logs from before the last reboot. diff --git a/liblog/log_read.c b/liblog/log_read.c index cfc8a7aca..fb8675779 100644 --- a/liblog/log_read.c +++ b/liblog/log_read.c @@ -797,6 +797,14 @@ int android_logger_list_read(struct logger_list *logger_list, } if (logger_list->start.tv_sec || logger_list->start.tv_nsec) { + if (logger_list->mode & ANDROID_LOG_WRAP) { + // ToDo: alternate API to allow timeout to be adjusted. + ret = snprintf(cp, remaining, " timeout=%u", + ANDROID_LOG_WRAP_DEFAULT_TIMEOUT); + ret = min(ret, remaining); + remaining -= ret; + cp += ret; + } ret = snprintf(cp, remaining, " start=%" PRIu32 ".%09" PRIu32, logger_list->start.tv_sec, logger_list->start.tv_nsec); From 562e513d4b3860d3ec831a66817fa141ce17b77f Mon Sep 17 00:00:00 2001 From: Kristian Monsen Date: Fri, 5 Jun 2015 14:10:12 -0700 Subject: [PATCH 4/6] logcat: Add long arguments to logcat, support for pid filter Bug: 21615139 Change-Id: I3e63e43067f8089c18658e4100e901fb2a9630ae --- logcat/logcat.cpp | 49 ++++++++++++++++++++++++++++++++++++----------- 1 file changed, 38 insertions(+), 11 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 0c59f2307..5f73f49a7 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -286,7 +287,8 @@ static void show_help(const char *cmd) " represents an automatic quicker pruning for the noisiest\n" " UID as determined by the current statistics.\n" " -P ' ...' set prune white and ~black list, using same format as\n" - " printed above. Must be quoted.\n"); + " printed above. Must be quoted.\n" + " --pid= Only prints logs from the given pid.\n"); fprintf(stderr,"\nfilterspecs are a series of \n" " [:priority]\n\n" @@ -348,15 +350,19 @@ static const char *multiplier_of_size(unsigned long value) static bool getSizeTArg(char *ptr, size_t *val, size_t min = 0, size_t max = SIZE_MAX) { - char *endp; - errno = 0; - size_t ret = (size_t) strtoll(ptr, &endp, 0); - - if (endp[0] != '\0' || errno != 0 ) { + if (!ptr) { return false; } - if (ret > max || ret < min) { + char *endp; + errno = 0; + size_t ret = (size_t)strtoll(ptr, &endp, 0); + + if (endp[0] || errno) { + return false; + } + + if ((ret > max) || (ret < min)) { return false; } @@ -497,6 +503,7 @@ int main(int argc, char **argv) struct logger_list *logger_list; size_t tail_lines = 0; log_time tail_time(log_time::EPOCH); + size_t pid = 0; signal(SIGPIPE, exit); @@ -510,13 +517,33 @@ int main(int argc, char **argv) for (;;) { int ret; - ret = getopt(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:"); + int option_index = 0; + static const char pid_str[] = "pid"; + static const struct option long_options[] = { + { pid_str, required_argument, NULL, 0 }, + { NULL, 0, NULL, 0 } + }; + + ret = getopt_long(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:", + long_options, &option_index); if (ret < 0) { break; } - switch(ret) { + switch (ret) { + case 0: + // One of the long options + if (long_options[option_index].name == pid_str) { + // ToDo: determine runtime PID_MAX? + if (!getSizeTArg(optarg, &pid, 1)) { + logcat_panic(true, "%s %s out of range\n", + long_options[option_index].name, optarg); + } + break; + } + break; + case 's': // default to all silent android_log_addFilterRule(g_logformat, "*:s"); @@ -838,9 +865,9 @@ int main(int argc, char **argv) dev = devices; if (tail_time != log_time::EPOCH) { - logger_list = android_logger_list_alloc_time(mode, tail_time, 0); + logger_list = android_logger_list_alloc_time(mode, tail_time, pid); } else { - logger_list = android_logger_list_alloc(mode, tail_lines, 0); + logger_list = android_logger_list_alloc(mode, tail_lines, pid); } const char *openDeviceFail = NULL; const char *clearFail = NULL; From f8bff87c65eeaa0a97ba904e8d815b07cc03c91e Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 30 Nov 2015 12:57:56 -0800 Subject: [PATCH 5/6] logcat: Add low hanging fruit long arguments Add long arguments file, rotate_kbytes, rotate_count, format, dividers, clear, buffer_size, last, buffer, binary, statistics and prune. Bug: 21615139 Change-Id: Ieb1bbe3d47e6711a1e91c74522630d39f8981621 --- logcat/logcat.cpp | 47 ++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 38 insertions(+), 9 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 5f73f49a7..1ed0dfbc2 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -257,13 +257,19 @@ static void show_help(const char *cmd) " -s Set default filter to silent.\n" " Like specifying filterspec '*:S'\n" " -f Log to file. Default is stdout\n" + " --file=\n" " -r Rotate log every kbytes. Requires -f\n" + " --rotate_kbytes=\n" " -n Sets max number of rotated logs to , default 4\n" - " -v Sets the log print format, where is:\n\n" + " --rotate_count=\n" + " -v Sets the log print format, where is:\n" + " --format=\n" " brief color epoch long monotonic printable process raw\n" " tag thread threadtime time usec UTC year zone\n\n" " -D print dividers between each log buffer\n" + " --dividers\n" " -c clear (flush) the entire log and exit\n" + " --clear\n" " -d dump the log and then exit (don't block)\n" " -t print only the most recent lines (implies -d)\n" " -t '